| Thursday, June 28th, 2012, 00:07 UTC | ||
| [00:07:59] | zombor (zombor!~zombor_@kohana/developer/zombor) has quit (Remote host closed the connection) | |
| [00:13:46] | Mousey (Mousey!~r0dent_@ross154.net) has quit (Remote host closed the connection) | |
| [00:14:31] | Xeneth (Xeneth!ccd69106@gateway/web/freenode/ip.204.214.145.6) has joined #mythtv | |
| [00:14:47] | Xeneth (Xeneth!ccd69106@gateway/web/freenode/ip.204.214.145.6) has left #mythtv () | |
| [00:41:37] | dblain (dblain!~dblain@c-76-127-227-175.hsd1.ma.comcast.net) has joined #mythtv | |
| [00:41:37] | dblain (dblain!~dblain@mythtv/developer/dblain) has joined #mythtv | |
| [00:41:37] | dblain (dblain!~dblain@c-76-127-227-175.hsd1.ma.comcast.net) has quit (Changing host) | |
| [00:43:14] | skd5aner (skd5aner!~skd5aner@cpe-071-071-242-134.carolina.res.rr.com) has quit (Read error: Connection reset by peer) | |
| [00:43:33] | skd5aner (skd5aner!~skd5aner@cpe-071-071-242-134.carolina.res.rr.com) has joined #mythtv | |
| [00:46:04] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has quit (Quit: Leaving.) | |
| [01:04:42] | dekarl1 (dekarl1!~dekarl@p4FCEE5FE.dip.t-dialin.net) has joined #mythtv | |
| [01:06:18] | dekarl (dekarl!~dekarl@p4FCEE39E.dip.t-dialin.net) has quit (Ping timeout: 265 seconds) | |
| [01:15:31] | amessina (amessina!~amessina@2001:470:1f11:a4:d6be:d9ff:fe8d:7c1e) has joined #mythtv | |
| [02:10:14] | DJDan (DJDan!~djdan@115-64-177-188.static.tpgi.com.au) has joined #mythtv | |
| [02:18:46] | dblain_ (dblain_!~dblain@c-76-127-227-175.hsd1.ma.comcast.net) has joined #mythtv | |
| [02:20:20] | DJDan_ (DJDan_!~djdan@115-64-177-188.static.tpgi.com.au) has joined #mythtv | |
| [02:23:38] | DJDan (DJDan!~djdan@115-64-177-188.static.tpgi.com.au) has quit (Ping timeout: 265 seconds) | |
| [02:51:26] | DJDan_ (DJDan_!~djdan@115-64-177-188.static.tpgi.com.au) has quit (Remote host closed the connection) | |
| [02:59:21] | NightMonkey (NightMonkey!~NightrMon@pdpc/supporter/professional/nightmonkey) has quit (Quit: Body blow! Body blow!) | |
| [03:08:51] | dblain_ is now known as dblain | |
| [03:09:03] | dblain (dblain!~dblain@mythtv/developer/dblain) has joined #mythtv | |
| [03:09:03] | dblain (dblain!~dblain@c-76-127-227-175.hsd1.ma.comcast.net) has quit (Changing host) | |
| [03:24:13] | wahrhaft (wahrhaft!~quassel@cpe-24-210-71-26.columbus.res.rr.com) has quit (Remote host closed the connection) | |
| [03:25:36] | wahrhaft (wahrhaft!~quassel@cpe-24-210-71-26.columbus.res.rr.com) has joined #mythtv | |
| [03:54:06] | J-e-f-f-A_ (J-e-f-f-A_!~J-e-f-f-A@unaffiliated/j-e-f-f-a) has joined #mythtv | |
| [04:04:24] | jams (jams!~jams@cpe-184-58-217-97.wi.res.rr.com) has quit (*.net *.split) | |
| [04:09:58] | jams (jams!~jams@cpe-184-58-217-97.wi.res.rr.com) has joined #mythtv | |
| [04:20:14] | J-e-f-f-A_ (J-e-f-f-A_!~J-e-f-f-A@unaffiliated/j-e-f-f-a) has quit (Quit: Oh No!!!! ;-)) | |
| [04:22:18] | jams (jams!~jams@cpe-184-58-217-97.wi.res.rr.com) has quit (*.net *.split) | |
| [04:28:17] | jams (jams!~jams@cpe-184-58-217-97.wi.res.rr.com) has joined #mythtv | |
| [05:24:32] | wahrhaft (wahrhaft!~quassel@cpe-24-210-71-26.columbus.res.rr.com) has quit (Remote host closed the connection) | |
| [06:00:01] | SteveGoodey (SteveGoodey!~steve@host86-160-43-123.range86-160.btcentralplus.com) has joined #mythtv | |
| [06:08:20] | stichnot (stichnot!~chatzilla@192.55.54.40) has joined #mythtv | |
| [06:08:20] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [06:08:20] | stichnot (stichnot!~chatzilla@192.55.54.40) has quit (Changing host) | |
| [06:15:43] | SteveGoodey (SteveGoodey!~steve@host86-160-43-123.range86-160.btcentralplus.com) has quit (Remote host closed the connection) | |
| [06:25:23] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has joined #mythtv | |
| [07:01:49] | jarle (jarle!~jarle@70.84-234-133.customer.lyse.net) has quit (Ping timeout: 248 seconds) | |
| [07:14:08] | jarle (jarle!~jarle@70.84-234-133.customer.lyse.net) has joined #mythtv | |
| [07:26:44] | sraue (sraue!~stephan@xbmc/staff/sraue) has quit (Read error: No route to host) | |
| [07:37:09] | J-e-f-f-A (J-e-f-f-A!~J-e-f-f-A@pool-71-184-254-79.bstnma.fios.verizon.net) has quit (Ping timeout: 246 seconds) | |
| [07:39:17] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has quit (Quit: Leaving.) | |
| [07:41:34] | sraue (sraue!~stephan@xbmc/staff/sraue) has joined #mythtv | |
| [08:55:50] | MaverickTech (MaverickTech!~MaverickT@111.86.233.220.static.exetel.com.au) has quit (Ping timeout: 250 seconds) | |
| [09:02:12] | MaverickTech (MaverickTech!~MaverickT@111.86.233.220.static.exetel.com.au) has joined #mythtv | |
| [09:37:51] | Agrajag- (Agrajag-!~filip@c211-30-195-162.artrmn3.nsw.optusnet.com.au) has joined #mythtv | |
| [10:03:49] | ** stuarta admires the rasberry pi the guys in the office are playing with ** | |
| [10:21:22] | amessina (amessina!~amessina@2001:470:1f11:a4:d6be:d9ff:fe8d:7c1e) has quit (Quit: Konversation terminated!) | |
| [10:21:44] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has quit (Ping timeout: 244 seconds) | |
| [10:23:11] | amessina (amessina!~amessina@2001:470:1f11:a4:d6be:d9ff:fe8d:7c1e) has joined #mythtv | |
| [10:27:52] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has joined #mythtv | |
| [10:44:10] | amessina (amessina!~amessina@2001:470:1f11:a4:d6be:d9ff:fe8d:7c1e) has quit (Quit: Konversation terminated!) | |
| [11:47:33] | coling (coling!~colin@cpc7-sgyl36-2-0-cust267.18-2.cable.virginmedia.com) has quit (Ping timeout: 248 seconds) | |
| [11:49:16] | Chutt (Chutt!~ijr@cpe-24-29-225-175.neo.res.rr.com) has quit (Read error: Connection reset by peer) | |
| [11:49:42] | Chutt (Chutt!~ijr@cpe-24-29-225-175.neo.res.rr.com) has joined #mythtv | |
| [11:49:47] | Goga777 (Goga777!~Goga777@2.95.141.178) has joined #mythtv | |
| [11:56:03] | stuartm: | still not really played with mine yet |
| [11:56:29] | peitolm: | ditto |
| [12:04:21] | stuarta: | not even bought one :) |
| [12:08:22] | stuarta: | i have to make do looking at other peoples |
| [12:16:24] | zombor (zombor!~zombor_@65.29.231.135) has joined #mythtv | |
| [12:16:24] | zombor (zombor!~zombor_@65.29.231.135) has quit (Changing host) | |
| [12:16:25] | zombor (zombor!~zombor_@kohana/developer/zombor) has joined #mythtv | |
| [12:50:24] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has joined #mythtv | |
| [13:31:44] | coling (coling!~colin@cpc7-sgyl36-2-0-cust267.18-2.cable.virginmedia.com) has joined #mythtv | |
| [13:40:58] | rsiebert (rsiebert!~quassel@g224248070.adsl.alicedsl.de) has joined #mythtv | |
| [13:41:51] | rsiebert_ (rsiebert_!~quassel@g224248079.adsl.alicedsl.de) has quit (Ping timeout: 246 seconds) | |
| [14:05:43] | stichnot: | hmm... now I'm seeing similar memory growth of mythfrontend during playback, roughly 1MB growth in VIRT and RES every 5 seconds. Similar growth in mythlogserver. But it disappears when I run with "-v none". |
| [14:26:12] | Vernon_at_work (Vernon_at_work!~singv003@lightcloud.verns.net) has quit (Remote host closed the connection) | |
| [14:27:02] | Vernon_at_work (Vernon_at_work!~singv003@lightcloud.verns.net) has joined #mythtv | |
| [14:34:51] | Goga777 (Goga777!~Goga777@2.95.141.178) has quit (Read error: Connection reset by peer) | |
| [14:38:44] | Jordack (Jordack!~jordack@h69-131-44-221.plmomi.dedicated.static.tds.net) has joined #mythtv | |
| [14:59:08] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has quit (Ping timeout: 240 seconds) | |
| [15:15:06] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has joined #mythtv | |
| [15:55:45] | cattelan_away is now known as cattelan | |
| [16:27:38] | stichnot (stichnot!~chatzilla@192.55.54.40) has joined #mythtv | |
| [16:27:38] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [16:27:38] | stichnot (stichnot!~chatzilla@192.55.54.40) has quit (Changing host) | |
| [16:36:20] | NightMonkey (NightMonkey!~NightrMon@pdpc/supporter/professional/nightmonkey) has joined #mythtv | |
| [16:36:43] | joki (joki!~joki@p54862FDD.dip.t-dialin.net) has quit (Ping timeout: 265 seconds) | |
| [16:36:45] | joki- (joki-!~joki@p5486364E.dip.t-dialin.net) has joined #mythtv | |
| [16:36:56] | joki- is now known as joki | |
| [16:37:22] | kth (kth!~kth@unaffiliated/kth) has joined #mythtv | |
| [16:55:57] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has quit (Remote host closed the connection) | |
| [16:56:48] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has joined #mythtv | |
| [17:13:54] | kormoc (kormoc!~kormoc@mythtv/developer/kormoc) has joined #mythtv | |
| [17:24:41] | kth (kth!~kth@unaffiliated/kth) has quit (Quit: Leaving.) | |
| [17:24:44] | knightr_ (knightr_!~knightr@69-165-170-178.dsl.teksavvy.com) has joined #mythtv | |
| [17:28:26] | knightr__ (knightr__!~knightr@69-165-170-178.dsl.teksavvy.com) has quit (Ping timeout: 265 seconds) | |
| [17:29:10] | stichnot (stichnot!~chatzilla@192.55.54.40) has joined #mythtv | |
| [17:29:10] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [17:29:10] | stichnot (stichnot!~chatzilla@192.55.54.40) has quit (Changing host) | |
| [17:33:47] | Lomion0815 (Lomion0815!~markus@178-191-190-4.adsl.highway.telekom.at) has joined #mythtv | |
| [17:38:56] | Sharky112065 is now known as Sharky-Sleep | |
| [17:48:50] | SteveGoodey (SteveGoodey!~steve@host86-160-43-123.range86-160.btcentralplus.com) has joined #mythtv | |
| [17:55:39] | Lomion0815 (Lomion0815!~markus@178-191-190-4.adsl.highway.telekom.at) has quit (Quit: leaving) | |
| [18:02:43] | knightr_ (knightr_!~knightr@69-165-170-178.dsl.teksavvy.com) has quit (Ping timeout: 252 seconds) | |
| [18:20:59] | sraue (sraue!~stephan@xbmc/staff/sraue) has quit (Ping timeout: 245 seconds) | |
| [18:35:06] | sraue (sraue!~stephan@xbmc/staff/sraue) has joined #mythtv | |
| [18:54:36] | ThisNewGuy2 (ThisNewGuy2!ad4691d0@gateway/web/freenode/ip.173.70.145.208) has quit (Ping timeout: 245 seconds) | |
| [18:56:47] | danielk22: | Beirdo: I've added a devel/ceton icc builder to the master.cfg, can you take a look at it when you get a chance? |
| [19:14:55] | Defense|Twin (Defense|Twin!~jepz@c217226.adsl.hansenet.de) has joined #mythtv | |
| [19:36:26] | jarle (jarle!~jarle@70.84-234-133.customer.lyse.net) has quit (Remote host closed the connection) | |
| [19:37:35] | Beirdo: | sure. It might not be for a wee bit, but I'll definitely get to it today |
| [19:40:48] | jarle (jarle!~jarle@70.84-234-133.customer.lyse.net) has joined #mythtv | |
| [20:09:40] | knightr (knightr!~knightr@mythtv/developer/knightr) has joined #mythtv | |
| [20:17:03] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has quit (Remote host closed the connection) | |
| [20:17:47] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has joined #mythtv | |
| [20:21:21] | stichnot (stichnot!~chatzilla@192.55.55.37) has joined #mythtv | |
| [20:21:21] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [20:21:21] | stichnot (stichnot!~chatzilla@192.55.55.37) has quit (Changing host) | |
| [20:21:39] | squidly (squidly!~squidly@HoodLUG/member/squidly) has joined #mythtv | |
| [20:21:42] | squidly (squidly!~squidly@HoodLUG/member/squidly) has left #mythtv ("So long and thanks for all the fish!") | |
| [20:22:12] | stichnot (stichnot!~chatzilla@192.55.55.37) has joined #mythtv | |
| [20:22:12] | stichnot (stichnot!~chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [20:22:12] | stichnot (stichnot!~chatzilla@192.55.55.37) has quit (Changing host) | |
| [20:52:21] | skd5aner (skd5aner!~skd5aner@cpe-071-071-242-134.carolina.res.rr.com) has quit (Ping timeout: 246 seconds) | |
| [20:54:35] | dmfrey (dmfrey!~dmfrey@webdefence.cluster-h.websense.net) has quit (Quit: Ex-Chat) | |
| [20:58:42] | Defense|Twin (Defense|Twin!~jepz@c217226.adsl.hansenet.de) has quit (Remote host closed the connection) | |
| [21:06:14] | SteveGoodey (SteveGoodey!~steve@host86-160-43-123.range86-160.btcentralplus.com) has quit (Remote host closed the connection) | |
| [21:25:43] | Agrajag- (Agrajag-!~filip@c211-30-195-162.artrmn3.nsw.optusnet.com.au) has left #mythtv () | |
| [21:29:24] | Beirdo: | danielk22: I don't see the changes in git. Did you do them locally? |
| [21:34:53] | stichnot (stichnot!chatzilla@nat/intel/x-cqxkifyxlymwagcx) has joined #mythtv | |
| [21:34:53] | stichnot (stichnot!chatzilla@mythtv/developer/stichnot) has joined #mythtv | |
| [21:34:53] | stichnot (stichnot!chatzilla@nat/intel/x-cqxkifyxlymwagcx) has quit (Changing host) | |
| [21:39:34] | Captain_Murdoch (Captain_Murdoch!~Captain_M@mythtv/developer/CaptainMurdoch) has quit (Quit: Leaving) | |
| [21:40:04] | Captain_Murdoch (Captain_Murdoch!~Captain_M@ctp-lxut07.bc2va.org) has joined #mythtv | |
| [21:40:05] | Captain_Murdoch (Captain_Murdoch!~Captain_M@ctp-lxut07.bc2va.org) has quit (Changing host) | |
| [21:40:05] | Captain_Murdoch (Captain_Murdoch!~Captain_M@mythtv/developer/CaptainMurdoch) has joined #mythtv | |
| [22:11:42] | Jordack (Jordack!~jordack@h69-131-44-221.plmomi.dedicated.static.tds.net) has quit () | |
| [22:29:05] | danielk22: | Beirdo: Just pushed them |
| [22:29:39] | Beirdo: | K :) |
| [22:30:15] | Beirdo: | don't think the filter line is right |
| [22:30:21] | Beirdo: | the branch is devel/ceton |
| [22:31:04] | Beirdo: | other than that, looks about right from here |
| [22:32:46] | Beirdo: | would you like me to tweak that and put it live? |
| [22:32:55] | stichnot: | Beirdo, danielk22, stuartm: Have any of you tried running mythfrontend -v all or -v most and watching the memory sizes? I'm seeing rapid growth of the mythfrontend and mythlogserver processes when lots of logging is going on. I tried throwing a QCoreApplication::sendPostedEvents(NULL, QEvent::DeferredDelete); wherever I found a processEvents(), but to no effect. |
| [22:34:02] | Beirdo: | stichnot: no. It is quite likely you are overwhelming things, it's only designed to handle around 1000 messages a second on average with the current setup |
| [22:34:17] | Beirdo: | so crap is piling up in the queues |
| [22:35:00] | stichnot: | Beirdo: plenty of logs are being written out, and the memory size never drops even after playback ends and log messages stop. |
| [22:36:10] | stichnot: | e.g. after 20 minutes of playback, both processes grew by more than 400MB, during which 142K lines of logs totalling 18MB was written |
| [22:36:19] | Beirdo: | I'll take a look later on |
| [22:36:23] | Beirdo: | yeah |
| [22:36:24] | stichnot: | ok,thanks. |
| [22:36:28] | Beirdo: | you were killing it |
| [22:36:46] | Beirdo: | 20 min = 1200s |
| [22:36:55] | Beirdo: | 142k/1200 > 1000 |
| [22:37:11] | stichnot: | and did I mention ION? :) |
| [22:37:17] | Beirdo: | as I said, it only does about 1000 messages/s |
| [22:37:37] | Beirdo: | which I can look at tweaking, but it may end up using more CPU |
| [22:37:54] | Beirdo: | ION is irrelevant |
| [22:37:59] | Beirdo: | time is time is time. |
| [22:38:16] | Beirdo: | it's based on poll times, primarily |
| [22:39:13] | Beirdo: | it is likely we need to decrease spew in -v all anyways |
| [22:39:17] | Beirdo: | what log level? |
| [22:39:53] | stichnot: | mythfrontend -v important,general,playback,vbi --logpath /var/log/mythtv/full/ --syslog local7 --nodblog |
| [22:40:02] | Beirdo: | so info |
| [22:40:09] | stichnot: | right |
| [22:40:18] | Beirdo: | yeah, there's likely a LOT in info still that should be bumped down to debug |
| [22:40:31] | stichnot: | my CBS recordings have a huge amount of VBI spew, which is why I noticed |
| [22:40:34] | Beirdo: | we really haven't gone through and thought about it much |
| [22:40:51] | stichnot: | so you're saying if the logging is reduced, I should suddenly see no memory growth? |
| [22:40:54] | Beirdo: | VBI is a perfect example of one that should have stuff moved to debug level |
| [22:41:07] | Beirdo: | quite likely so |
| [22:41:27] | stichnot: | does that mean the memory is truly leaked in this case? |
| [22:41:31] | Beirdo: | try at --loglevel crit or something |
| [22:41:36] | Beirdo: | possibly |
| [22:41:49] | Beirdo: | depends on what's doing it and where |
| [22:41:51] | stichnot: | I can just try an HDPVR recording without any VBI info |
| [22:42:27] | Beirdo: | it's also possible that some of the code sending logs has memory leaks in the logging message generation before calling LOG() |
| [22:42:35] | Beirdo: | but that's not terribly probably |
| [22:43:02] | stichnot: | that's a good point, I should verify that |
| [22:43:33] | Beirdo: | we have done silly things in the past after all |
| [22:43:34] | Beirdo: | :) |
| [22:44:21] | stichnot: | fwiw, I think it's a problem if my i7 backend cannot produce "-v all --loglevel debug" logs, which I occasionally want for hard-to-trigger problems |
| [22:44:25] | Beirdo: | and, in all likelihood, we will again in the future |
| [22:44:46] | Beirdo: | I have *never* needed that much logging |
| [22:44:48] | Beirdo: | not once |
| [22:45:11] | stichnot: | sometimes I'm desperate :) |
| [22:45:22] | Beirdo: | and to be quite honest here, that much logging *used to* kill any box as the timing would be obliterated |
| [22:45:38] | Beirdo: | and if we can support that at all, I'd be quite happy |
| [22:46:04] | Beirdo: | doesn't obliterate it as bad as valgrind, of course :) |
| [22:46:36] | stichnot: | now that I think about it, I doubt the log-generating code has a particular leak, as I would have noticed it long ago |
| [22:46:52] | Beirdo: | probably not, but it's something to be aware of |
| [22:47:02] | Beirdo: | as I said, not terribly probable |
| [22:47:07] | stichnot: | yep |
| [22:47:29] | Beirdo: | I think the real issue will be found in overrunning queues |
| [22:47:50] | Beirdo: | do you still have any old logs at that level from pre-zeromq? |
| [22:48:34] | Beirdo: | if so, if you could calculate about how many messages/sec it generated, that could be useful info |
| [22:49:03] | Beirdo: | might be able to get away with a peak average of around 10k msgs/sec |
| [22:49:27] | Beirdo: | this was expected tuning, BTW :) |
| [22:49:28] | stichnot: | logs at which level? |
| [22:49:39] | Beirdo: | at spew-hard :) |
| [22:50:03] | Beirdo: | getting an idea of the max msgs/s we generate in a program would be useful info |
| [22:50:06] | stichnot: | you mean e.g. CBS recordings with tons of VBI spew? |
| [22:50:32] | Beirdo: | sure, or anything else that logged buttloads successfully before |
| [22:50:33] | stichnot: | if so, I probably have a number of those |
| [22:51:11] | Beirdo: | in normal use, we are lucky if we hit about 10msgs/s on average in the log server |
| [22:51:35] | Beirdo: | but once you unmask more sources and --loglevel debug, yeah, that grows rapidly |
| [22:52:29] | Beirdo: | and to speed it up more (BTW), running with no console logging can be helpful :) |
| [22:52:53] | Beirdo: | as then it's not updating the console which is fairly slow |
| [22:54:36] | Beirdo: | oh crud, still need to debork the dblogging pacing |
| [22:56:48] | stichnot: | Beirdo: check out the backend log attached to #10647 |
| [22:56:48] | ** MythLogBot http://code.mythtv.org/trac/ticket/10647 ** | |
| [22:58:27] | stichnot: | my philosophy is that it's a lot easier to prune excess log files than to reproduce a problem with more logging, so I just keep lots of logging by default |
| [22:58:45] | Beirdo: | what about that log? |
| [22:59:17] | Beirdo: | that's about 44000 lines in about 3600s |
| [22:59:47] | Beirdo: | about 10/s on average (a bit higher) |
| [22:59:50] | stichnot: | hmm, let me have another look |
| [23:00:55] | Beirdo: | the basic issue I think we are hitting: |
| [23:01:04] | Beirdo: | http://en.wikipedia.org/wiki/Leaky_bucket |
| [23:01:20] | Beirdo: | I basically need to drill bigger holes in the bottom of the bucket |
| [23:03:06] | Beirdo: | that's the basic queuing theory in play here (gotta love queuing theory!) |
| [23:06:22] | stichnot: | so Beirdo, 142K/1200 is actually 118, which is well below 1000... |
| [23:06:35] | Beirdo: | hmm |
| [23:06:38] | Beirdo: | so it is |
| [23:06:47] | Beirdo: | maybe my brain is off, and we max at 100/s |
| [23:07:11] | Beirdo: | it's something I'll have to fiddle with in a couple hours :) |
| [23:07:29] | stichnot: | and in that backend log, if you look at the section between 06:28:00 and 06:30:00, you get about 40K messages in 120 seconds, or 333 messages/sec |
| [23:07:52] | stichnot: | afaict, the backend was doing just fine with that |
| [23:08:00] | Beirdo: | yeah, but that's peaking... Hmmm |
| [23:08:27] | Beirdo: | I'll make sure I can reproduce and tweak. Good to remember this before 0.26 :) Thanks |
| [23:08:30] | stichnot: | "peaking"? that's a full 2 minutes |
| [23:08:54] | Beirdo: | well, yeah, but it might have stored that in memory and spewed it anyways |
| [23:09:36] | stichnot: | yeah, I have no idea how long it took to write it all out |
| [23:09:39] | Beirdo: | basically, the mechanism is like a bucket... the bucket happens to be huge, but if the packets fit in the bucket, they will come back out into the log |
| [23:09:56] | Beirdo: | if you overflow the bucket, THOSE messages are likely gonna be leaked |
| [23:10:39] | Beirdo: | as we can't control the input flow rate effectively, we need to make sure the output flow rate is sufficient |
| [23:11:12] | Beirdo: | oh, and if the bucket's full, the bucket you are filling it from stops pouring into it (if it works right) |
| [23:11:20] | Beirdo: | but then IT can overflow (in the frontend) |
| [23:11:35] | Beirdo: | the joy of multiple queues :) |
| [23:12:04] | amejia (amejia!~andres@xbmc/staff/amejia) has joined #mythtv | |
| [23:12:04] | Beirdo: | so I have to double-check the various overflow responses for the zeromq queue types in use |
| [23:12:19] | Beirdo: | and then check the polling intervals, etc. |
| [23:13:10] | stichnot: | some more data: by the end of this 20-minute playback, CPU usage of mythfrontend and mythlogserver were both at around 50%, so I could imagine saturation. However, after a mythfrontend restart, both are at about 25%. I know little enough about queuing theory to say anything about the likelihood of overflowing, but I do note that the rate of growth seemed consistent throughout the 20 minutes |
| [23:13:27] | Beirdo: | K |
| [23:13:40] | Beirdo: | should be simple enough to test on my end |
| [23:13:58] | Beirdo: | what you can do to see how fast the logserver consumes them... |
| [23:14:08] | Beirdo: | one sec, let me find the line number |
| [23:14:52] | Beirdo: | http://code.mythtv.org/cgit/mythtv/tree/mytht . . . ver.cpp#n882 |
| [23:15:12] | Beirdo: | uncomment that line, and then... |
| [23:15:26] | Beirdo: | killall mythlogserver ; mythlogserver |
| [23:15:36] | Beirdo: | i.e. manually run it so you have the console |
| [23:15:43] | stichnot: | ok |
| [23:15:54] | stichnot: | I'll give it a try right now |
| [23:16:08] | Beirdo: | once a second it should say how many messages it went through in that second |
| [23:17:00] | Beirdo: | I left in all my troubleshooting couts for now (commented out) |
| [23:18:11] | stichnot: | generally stays in the low 100s, or less than 100 |
| [23:18:26] | stichnot: | usually >60 |
| [23:18:34] | Beirdo: | with it spewing? |
| [23:18:45] | stichnot: | yes, but let me double check |
| [23:20:01] | stichnot: | yep, its favorite message is something like "AFD: VBI: Unknown descriptor: 153" |
| [23:20:50] | stichnot: | and of course every single decoded cc708 character is logged |
| [23:21:01] | stichnot: | in its own separate message |
| [23:21:03] | danielk22: | Beirdo: If you can get that builder to go — please make any changes you like. |
| [23:21:15] | Beirdo: | danielk22: OK, will do, one moment |
| [23:23:05] | eaxxae (eaxxae!~eaxxae@unaffiliated/eaxxae) has joined #mythtv | |
| [23:23:13] | stichnot: | If the log server chooses to drop some messages, it would be nice if it would indicate that in the logs, otherwise it could be mighty confusing trying to follow the logs when debugging |
| [23:23:37] | MythBuild (MythBuild!~MythBuild@alcor.mythtv.org) has quit (Remote host closed the connection) | |
| [23:23:47] | MythBuild (MythBuild!~MythBuild@alcor.mythtv.org) has joined #mythtv | |
| [23:23:51] | Beirdo: | hopefully that should catch it |
| [23:24:26] | Beirdo: | danielk22: should be good to go |
| [23:24:50] | Beirdo: | let's try it |
| [23:25:03] | Beirdo: | MythBuild: force build ceton-linux-64bit-icc now |
| [23:25:03] | MythBuild: | build #0 forced |
| [23:25:03] | MythBuild: | I'll give a shout when the build finishes |
| [23:25:33] | stichnot: | but stepping back, I find the memory growth very fishy, and not explainable by oversaturation or dropped logs. It looks very similar to the recent mythbackend growth problem. |
| [23:25:45] | Beirdo: | stichnot: well, depending on the queuing mechanisms IN zeromq, we may not ever see if it drops |
| [23:26:06] | Beirdo: | there maybe a missing spot in the frontend |
| [23:26:34] | Beirdo: | I don't think there is in the logserver threads, but that's something I need to read again carefully |
| [23:26:42] | stichnot: | as I said before, I tried applying the same "fix" everywhere I saw a processEvents, but to no effect |
| [23:26:50] | Beirdo: | heh |
| [23:27:03] | Beirdo: | did you actually kill the mythlogserver in your tests? |
| [23:27:10] | stichnot: | yeah |
| [23:27:15] | Beirdo: | as if you don't, it may still be running the old code |
| [23:27:16] | Beirdo: | K |
| [23:27:20] | stichnot: | I start with "killall mythfrontend mythlogserver" |
| [23:27:27] | stichnot: | then I usually have to kill mythfrontend again :) |
| [23:28:30] | Beirdo: | the one place I'm somewhat concerned in is the LogForwardThread |
| [23:28:56] | Beirdo: | ah yes, and I force a processEvents every 127 messages in a burst |
| [23:28:59] | stichnot: | and as I said a couple days ago, I'm not very comfortable with the mythbackend growth fix without understanding why the zeromq addition triggered the growth |
| [23:29:04] | Beirdo: | err, every 128 |
| [23:29:36] | Beirdo: | probably pushed a race condition past its limits. |
| [23:29:37] | stichnot: | we may have just shifted things around without addressing the root cause |
| [23:29:40] | Beirdo: | or soemthign |
| [23:29:43] | stichnot: | yeah |
| [23:34:09] | Beirdo: | the only way to find the root cause is to run valgrind with --show-reachable=yes on a leak-check run |
| [23:34:41] | Beirdo: | but it will be SLOW, and may need some help to get past some of our stuff. I waited 40min for the backend to come up, and it didn't |
| [23:35:13] | Beirdo: | then you run the thing for a while, see what's left over when we quit the program, and where it came from |
| [23:35:24] | Beirdo: | you'd need the verbose tracking, etc |
| [23:35:58] | Beirdo: | that will definitively tell us WHAT is sticking around |
| [23:36:08] | Beirdo: | and then we could be sure to fix the handling of that data |
| [23:37:42] | zombor (zombor!~zombor_@kohana/developer/zombor) has quit (Remote host closed the connection) | |
| [23:38:57] | Sharky-Sleep is now known as Sharky112065 | |
| [23:39:38] | stichnot: | I don't think valgrind will help if Qt is holding onto the memory and then releases it on a clean exit |
| [23:40:19] | Beirdo: | yes it will |
| [23:40:35] | Beirdo: | there are ways :) |
| [23:40:52] | Beirdo: | like put abort() in the cleanup guard function |
| [23:41:05] | Beirdo: | don't let Qt clean up |
| [23:41:49] | Beirdo: | and you'll probably get a honking huge coredump too |
| [23:42:18] | stichnot: | ok |
| [23:42:25] | Beirdo: | worth a try :) |
| [23:42:51] | stichnot: | still, I hope someone else can confirm the growth... |
| [23:43:22] | Beirdo: | I'll try once I'm home |
| [23:43:28] | stichnot: | cool, thanks |
| [23:43:32] | Beirdo: | it shouldn't be too hard to make the frontend spew :) |
| [23:44:06] | stichnot: | I will try on the backend as well. I haven't really given it a good log-workout yet |
| [23:44:21] | Beirdo: | K. |
| [23:45:00] | Beirdo: | I guess I could put in message counting in the clients too |
| [23:48:15] | stichnot (stichnot!chatzilla@mythtv/developer/stichnot) has quit (Ping timeout: 244 seconds) | |
| [23:48:15] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has quit (Quit: Leaving.) | |
| [23:53:56] | mrand (mrand!~mrand@ubuntu/member/mrand) has quit (Ping timeout: 244 seconds) | |
| [23:54:19] | Beirdo: | I think I'll start heading home soon |
IRC Logs collected by
BeirdoBot.
Please use the above link to report any bugs.