| Friday, June 3rd, 2011, 00:03 UTC | ||
| [00:03:38] | pheld (pheld!~heldal@cl-5.osl-01.no.sixxs.net) has quit (Quit: Leaving.) | |
| [00:11:08] | knightr (knightr!~knightr@mythtv/developer/knightr) has joined #mythtv | |
| [00:17:06] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Ping timeout: 250 seconds) | |
| [00:17:44] | Gibby (Gibby!~Gibby@204.118.10.244) has joined #mythtv | |
| [00:31:12] | markk (markk!~mark@cm180.omega173.maxonline.com.sg) has joined #mythtv | |
| [00:47:11] | gigem (gigem!~david@mythtv/developer/gigem) has quit (Remote host closed the connection) | |
| [00:47:41] | gigem (gigem!~david@mythtv/developer/gigem) has joined #mythtv | |
| [00:52:05] | zombor (zombor!~zombor_@kohana/developer/zombor) has joined #mythtv | |
| [01:06:00] | taylorr: | markk: we found out earlier today that Beirdo was using a custom kernel with different scheduling algorithms – since he didn't seem to have the problem with large delays like us he's going to retry his tests with a stock Ubuntu kernel |
| [01:07:45] | taylorr: | sphery: I don't have a /proc/config.gz |
| [01:09:37] | markk: | taylorr: cool. I had a couple of power cuts in the night. fwiw – I'm working up some extra ringbuffer monitoring stuff which I'm going to hook into a new osd window. will show recent read rate (i.e. what the decoder/demuxer is asking for), recent link speed (i.e. network speed), ringbuffer buffer utilisation etc. will also add some things like fps, video buffers available, filename etc etc |
| [01:10:12] | markk: | and after that, I'm going to start looking at adjusting the ringbuffer buffer size |
| [01:10:12] | taylorr: | markk: sweet! – I'm determined to get to the bottom of this. |
| [01:11:08] | taylorr: | and hopefully we'll be able to find out why we have such hideous delays with REQUEST_BLOCK on the backend |
| [01:31:36] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has quit (Remote host closed the connection) | |
| [01:36:29] | taylorr (taylorr!~taylorr@cpe-173-095-144-220.nc.res.rr.com) has joined #mythtv | |
| [01:36:29] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has joined #mythtv | |
| [01:36:29] | taylorr (taylorr!~taylorr@cpe-173-095-144-220.nc.res.rr.com) has quit (Changing host) | |
| [01:39:03] | taylorr: | Beirdo: looks like Ubuntu has "preempt" kernels |
| [01:39:38] | taylorr: | says it's for "low latency servers" :) |
| [01:40:12] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has quit (Remote host closed the connection) | |
| [01:52:33] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has joined #mythtv | |
| [01:52:54] | taylorr: | Beirdo: the "preempt" kernel didn't help :( |
| [02:02:36] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has quit (Remote host closed the connection) | |
| [02:05:11] | taylorr (taylorr!~taylorr@unaffiliated/elmojo) has joined #mythtv | |
| [02:07:35] | danielk22: | taylorr: I don't think scheduling is the cause of these delays. You would only get one such delay in the servicing of a request block, if you see a 480 ms round trip it's something else. |
| [02:09:16] | taylorr: | danielk22: that's what I'm trying to figure out – the reason we see the huge request block delays are due to the FUTEX_WAIT calls that are triggered by lock requests |
| [02:10:02] | taylorr: | since VERBOSE calls trigger lock accesses it makes the problem even worse when you add them to debug |
| [02:10:30] | taylorr: | in fact adding more verbosity on the backend makes loading MythVideo on the frontend insanely slow |
| [02:12:02] | danielk22: | taylorr: Just disable verbose locking, it's just there to make the logs pretty. You can just use the release version of the VERBOSE macro without locking and it will run like gangbusters (while messing up the occasional line of the log). |
| [02:12:37] | taylorr: | danielk22: so --compile-type=release will automatically compile the lockless VERBOSE macro? |
| [02:13:26] | danielk22: | No, compile-type=release will use faster VERBOSE macros, but ones with locking. But you can just comment out the locking. |
| [02:13:37] | taylorr: | gotcha |
| [02:14:12] | taylorr: | danielk22: I'm wondering if I should put an assert inside the request_block function and get a gdb backtrace at that point |
| [02:15:10] | taylorr: | maybe one of the other threads becomes active when a request block is called |
| [02:16:14] | danielk22: | taylorr: I doubt it. I'd just put a bunch of verboses in there and narrow down which lines of code the main delay is occurring. |
| [02:16:44] | taylorr: | danielk22: I already did that :) it happens at the locks |
| [02:17:05] | taylorr: | if you unlock or lock it triggers a FUTEX_WAIT which doesn't return for 10 msec |
| [02:17:38] | taylorr: | so if I remove all the locking and change the VERBOSE to be lockless I bet it works great |
| [02:18:52] | taylorr: | the file transfer typically takes about 15 msec alone plus the socket write takes about the same so the meat of the transaction is about 30 msec – the locking adds considerably more |
| [02:20:29] | danielk22: | taylorr: I think you are chasing a heisenberg effect with the FUTEX_WAIT.. it may show up there when you debug, but nothing would run if the locks were really that slow. |
| [02:21:08] | taylorr: | going to try removing all locking and see |
| [02:21:31] | taylorr: | and I hope you are right about it being heisenberg in nature |
| [03:26:15] | Beirdo: | taylorr: you tried with a kernel with preempt ON, correct? |
| [03:26:23] | Beirdo: | mine has it off completely |
| [03:26:36] | taylorr: | Beirdo: yes |
| [03:26:43] | taylorr: | ok, cool |
| [03:27:07] | Beirdo: | I should go download a kernel before I forget so I can try with a "standard" Ubuntu kernel though |
| [03:40:24] | sunkan (sunkan!~sunkan@alva.zappa.cx) has quit (Read error: Operation timed out) | |
| [03:45:43] | sunkan (sunkan!~sunkan@alva.zappa.cx) has joined #mythtv | |
| [03:56:02] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has joined #mythtv | |
| [04:02:26] | andrewju (andrewju!~Miranda@81.200.112.228) has quit (Ping timeout: 259 seconds) | |
| [04:04:00] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has quit (Remote host closed the connection) | |
| [04:04:58] | Beirdo: | OK, rebooting the backend... this is always nerve-wracking (I have no video card in there) |
| [04:06:08] | Beirdo: | Linux mythbe 2.6.35-25-generic #44~lucid1-Ubuntu SMP Tue Jan 25 19:17:25 UTC 2011 x86_64 GNU/Linux |
| [04:06:13] | Beirdo: | OK, that should do |
| [04:09:19] | Beirdo: | it looks about the same as before (to me) |
| [04:10:50] | Beirdo: | unfortunately, I can't stay running this kernel as it doesn't have drivers for the analog side of my hvr2250 |
| [04:11:07] | taylorr: | Beirdo: thanks – I went through every backend thread with strace and found one thread that kicks in during the request_blocks |
| [04:11:21] | Beirdo: | oh? which one? |
| [04:11:30] | taylorr: | dunno, uploading it... |
| [04:11:34] | Beirdo: | K :) |
| [04:12:48] | Beirdo: | Gonna reboot back to the other kernel |
| [04:12:55] | taylorr: | Beirdo: http://mythtv.pastebin.ca/2073983 |
| [04:13:09] | taylorr: | any idea what that thread is doing |
| [04:13:21] | taylorr: | looks like it's trying to read a socket and timing out everytime |
| [04:14:12] | Beirdo: | can you backtrace that thread to find out which it is? |
| [04:14:27] | taylorr: | sure, lemme attach gdb |
| [04:15:20] | taylorr: | when I attached gdb directly to it the frontend stopped playing :( |
| [04:15:36] | Beirdo: | yeah, it will, it suspends the process |
| [04:15:53] | Beirdo: | as soon as you detach, it should be back running |
| [04:15:55] | taylorr: | it's the MythSocketThread |
| [04:16:27] | Beirdo: | interesting |
| [04:16:32] | taylorr: | wonder if it's causing some type of contention |
| [04:16:44] | Beirdo: | yeah, I guess it will still be receiving the messages from the frontend, won't it? |
| [04:16:56] | taylorr: | it only seems to kick in "exactly" when the request_blocks happen |
| [04:17:33] | taylorr: | is that the thread that gets the REQUEST_BLOCK and then sends the actually work to the 5 other threads? |
| [04:18:00] | Beirdo: | I believe so |
| [04:18:22] | Beirdo: | it's involved, I think. Not sure precisely |
| [04:22:36] | Beirdo: | an lsof -p `pidof mythbackend` could be instructive |
| [04:22:49] | Beirdo: | find out what fd 32 is connected to |
| [04:25:30] | Beirdo: | and I wonder just what all these FIFO are connected to |
| [04:37:51] | taylorr: | Beirdo: yeah, that's alot of pipes |
| [04:38:54] | taylorr: | maybe it's a connection for the MythSocketThread to the process worker threads |
| [04:40:29] | taylorr: | Beirdo: why do you think the MythSocketThread has so many of these -> 0.000108 read(32, 0x7fd6d8ff8d30, 128) = -1 EAGAIN (Resource temporarily unavailable) <0.000020> |
| [04:40:32] | Beirdo: | is fd 32 a fifo for you? |
| [04:40:38] | taylorr: | yes it is |
| [04:40:39] | Beirdo: | not sure |
| [04:40:55] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has joined #mythtv | |
| [04:41:13] | taylorr: | port 6543 is what is used to transmit the data back to the frontend |
| [04:41:20] | Beirdo: | correct |
| [04:41:30] | Beirdo: | AFAIK |
| [04:42:08] | zombor (zombor!~zombor_@kohana/developer/zombor) has quit (Remote host closed the connection) | |
| [04:42:28] | Beirdo: | let me go see what that thread does :) |
| [04:43:16] | Beirdo: | oooh, it uses pipes internally |
| [04:43:38] | taylorr: | wonder what port the REQUEST_BLOCK comes in on on the backend |
| [04:43:53] | Beirdo: | :6543 AFAIK |
| [04:44:01] | Beirdo: | same as it goes back out |
| [04:44:06] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has quit (Remote host closed the connection) | |
| [04:44:08] | Beirdo: | it's either 6543 or 6544 |
| [04:44:20] | taylorr: | Beirdo: I wonder why it's trying to read fd 32 and it says resource is temporary unavailable |
| [04:44:32] | taylorr: | wonder why that would happen |
| [04:45:12] | taylorr: | you figure it would sit on a select until something came in |
| [04:45:49] | Beirdo: | seems that it does a select, then it always checks the first pipe |
| [04:46:20] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has joined #mythtv | |
| [04:46:43] | taylorr: | Beirdo: where is that code? |
| [04:47:23] | Beirdo: | libs/libmythbase/mythsocketthread.cpp |
| [04:47:35] | Beirdo: | libmythdb in 0.24, I think |
| [04:48:56] | Beirdo: | I don't quite get the purpose of this |
| [04:51:45] | taylorr: | Beirdo: according to the strace it always does two reads to fd 32 – the first gets data and the second always times out |
| [04:51:54] | taylorr: | then it goes back to select |
| [04:51:57] | Beirdo: | yeah |
| [04:52:07] | taylorr: | why does it do that second one |
| [04:54:03] | Beirdo: | yeah, the one before the select is intentional (to empty the pipe before the select) |
| [04:54:21] | Beirdo: | it will often return -EAGAIN as teh pipe is empty |
| [04:55:03] | Beirdo: | interesting way to do it |
| [04:55:15] | tris (tris!tristan@2001:1868:a00a::4) has quit (Ping timeout: 255 seconds) | |
| [04:55:23] | Beirdo: | we are using a pair of pipes to wake the thread, essentially |
| [04:55:54] | Beirdo: | when something wants to wake it, they write a "0" into the write pipe, and that wakes the select on the read pipe |
| [04:56:05] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Read error: Connection reset by peer) | |
| [04:56:08] | taylorr: | Beirdo: it takes 60–80 msecs to read 128 from fd 32 |
| [04:56:15] | Gibby (Gibby!~Gibby@204.118.10.244) has joined #mythtv | |
| [04:56:27] | taylorr: | err, read 128 bytes |
| [04:56:33] | Beirdo: | up to 128 |
| [04:56:39] | Beirdo: | it's likely getting 1 byte |
| [04:56:45] | Beirdo: | (return value) |
| [04:56:48] | taylorr: | or 181 msec |
| [04:57:04] | taylorr: | wonder if that is where the delays are happening on the REQUEST_BLOCK |
| [04:57:43] | Beirdo: | looks more like the delay is on the select |
| [04:57:57] | Beirdo: | (time at the end of the line is how long that syscall took) |
| [04:58:09] | taylorr: | ah, yes |
| [04:58:15] | Beirdo: | which would make sense if we are waiting on something to wake it |
| [04:58:34] | Beirdo: | the WakeReadyReadThread above in the same file is what wakes it |
| [04:58:47] | Beirdo: | or a byte on any of the actual sockets |
| [04:59:50] | Beirdo: | I kinda like this mechanism, come to think of it |
| [05:00:58] | Beirdo: | further down is where it will actually send signals for each socket if they are ready to be read |
| [05:03:33] | Beirdo: | but yeah, that's the thread that starts the processing of messages coming in on the sockets |
| [05:03:49] | Beirdo: | it calls the callbacks to say data's available |
| [05:08:17] | Beirdo: | OK, so from mythbackend, one of the callbacks is MainServer::readyRead() |
| [05:08:51] | Beirdo: | which then gets a ProcessRequestThread to process it |
| [05:09:13] | Beirdo: | which eventually calls ReadPriv |
| [05:09:23] | taylorr: | Beirdo: making the requestBuffer a fixed array instead of a resizeable vector |
| [05:09:42] | Beirdo: | where's that? |
| [05:09:45] | taylorr: | who know if that takes much time |
| [05:09:51] | Beirdo: | could be |
| [05:09:56] | taylorr: | programs/mythbackend/filetransfer.cpp |
| [05:10:07] | Beirdo: | especially if it has to shrink/expand/shrink/expand |
| [05:11:27] | Beirdo: | ahh, that could help... be careful not to let it overflow though :) |
| [05:12:28] | taylorr: | it doesn't help |
| [05:12:35] | Beirdo: | it could use a "if (requestBuffer.size < blah) requestBuffer.resize() |
| [05:13:22] | Beirdo: | sorry.. requestBuffer.size() |
| [05:13:23] | Beirdo: | heh |
| [05:13:58] | taylorr: | wow, I put a timer in the requestBlock function and output a warning if over 150 msec |
| [05:14:14] | taylorr: | I see it take over 600 msecs sometimes to complete |
| [05:14:36] | Beirdo: | well, there is a 100ms wait on a lock in there at the beginning |
| [05:14:44] | Beirdo: | in a loop |
| [05:14:52] | taylorr: | huh, where at? |
| [05:14:58] | Beirdo: | dunno what turns on readLocked |
| [05:15:10] | taylorr: | I think I commented that out |
| [05:15:18] | Beirdo: | right at the top of FileTransfer::RequestBlock |
| [05:16:06] | Beirdo: | that's used by Stop and Pause |
| [05:16:06] | taylorr: | I have it commented out already :) |
| [05:16:29] | Beirdo: | so, basically to unpause :) |
| [05:17:36] | Beirdo: | unless the pginfo->UpdateInUseMark() is slow, perhaps? |
| [05:19:43] | taylorr: | where is that called from? |
| [05:20:14] | Beirdo: | right at the end of RequestBlock |
| [05:20:23] | Beirdo: | at least in master :) |
| [05:21:05] | taylorr: | Beirdo: could you put a timer for RequestBlock() execution and see if you are getting the 100+ msec times |
| [05:21:33] | Beirdo: | sure, you got a patch to simplify matters? |
| [05:21:48] | Beirdo: | that way we are timing at the same places |
| [05:21:50] | taylorr: | hold on a sec |
| [05:22:55] | taylorr: | http://mythtv.pastebin.ca/2073992 |
| [05:26:59] | Beirdo: | OK, in place, now just to wait for recording to stop, and I'll kick the backend |
| [05:28:10] | tris (tris!tristan@2001:1868:a00a::4) has joined #mythtv | |
| [05:42:59] | taylorr: | Beirdo: the MythSocketThread is the only active thread that could possibly cause an issue – unless there are transient threads getting created and killed quickly |
| [05:45:25] | Beirdo: | which is possible, but not that predictably, I'd think |
| [05:47:32] | okolsi: | taylorr: what kind of use case you are testing? SD recording streamed to remote frontend? |
| [05:48:09] | Beirdo: | 13min more recording to go |
| [05:48:26] | taylorr: | okolsi: no, a bursty matroska file |
| [05:50:41] | taylorr: | Beirdo: I wonder if this could have anything to do with the deep wait states of the core i* series of processors |
| [05:51:09] | taylorr: | since it's lightly loaded I could see it having to go in and out of those states |
| [05:51:22] | Beirdo: | well, my i7 isn't doing that |
| [05:51:23] | taylorr: | maybe I should run cpuburn or something |
| [05:51:33] | taylorr: | doing what? |
| [05:51:35] | Beirdo: | although... I'm often recording too |
| [05:51:49] | Beirdo: | going into deep wait states, etc. |
| [05:52:21] | Beirdo: | it rarely goes below 100% rated CPU speed |
| [05:53:12] | Beirdo: | that's using i7z |
| [05:53:24] | Beirdo: | oh look, one core is at half rated CPU speed |
| [05:53:45] | Beirdo: | but it ramps up so fast that I don't know how that could be the case |
| [05:53:57] | Beirdo: | and it never hits C3 or C6 on my box |
| [05:53:59] | taylorr: | yes, I doubt it's an issue |
| [05:54:10] | Beirdo: | I idle in C1 |
| [05:54:32] | taylorr: | it does seem to be better the less logging I have going on |
| [05:55:50] | Beirdo: | qthat does seem to sound like a thread interaction |
| [05:55:53] | taylorr: | maybe it's hypertheading related |
| [05:56:25] | Beirdo: | dunno, I use hyperthreading too, although I have more real cores to deal with |
| [05:56:54] | taylorr: | I don't see how the MythSocketThread and the 5 ProcessRequestThreads could have an issue |
| [05:57:07] | Beirdo: | they shouldn't |
| [05:57:28] | Beirdo: | from everything I've seen reading them, it doesn't make much sense to me either |
| [05:57:53] | Beirdo: | there's nothing else active on the system? |
| [05:58:14] | taylorr: | I guess we'll wait till you run with the timer patch and see if you experience the problem |
| [05:58:21] | Beirdo: | like no commflagging or anything of the sort? |
| [05:58:24] | taylorr: | no |
| [05:58:32] | Beirdo: | K |
| [05:58:46] | Beirdo: | I'll try out the test files again with that in |
| [05:58:48] | taylorr: | cpu stays near 0 |
| [06:01:02] | Beirdo: | OK, recording finished |
| [06:02:13] | taylorr: | Beirdo: weird if I attach strace to the MythSocketThread I don't get any RequestBlock more than 150 msecs |
| [06:02:22] | taylorr: | tell me that isn't strange |
| [06:02:27] | Beirdo: | hehe |
| [06:02:34] | Beirdo: | stupid heisenbugs |
| [06:02:45] | taylorr: | it's changing the timing of that thread |
| [06:02:54] | taylorr: | so maybe there is contention between the two |
| [06:02:58] | Beirdo: | minorly, but yeah |
| [06:03:30] | taylorr: | I went 10 minutes straight without a delay more than 150 msec |
| [06:03:33] | Beirdo: | I would think that with 2 cores/4 threads, you should be able to run at least 4 threads in parallel |
| [06:04:19] | Beirdo: | or at LEAST 2 with no contention of any sorts for CPU resources |
| [06:04:22] | taylorr: | I'll turn off hyperthreading tomorrow and see if anything changes |
| [06:04:59] | Beirdo: | heh, worth a try, I guess |
| [06:05:16] | Beirdo: | playing the BSG with that logging in |
| [06:05:36] | taylorr: | any thoughts on the strace phenomenon? |
| [06:06:02] | Beirdo: | not really, other than maybe you are affecting the timing, and that's all it needs to fix it |
| [06:06:12] | Beirdo: | which would be odd |
| [06:07:53] | taylorr: | wait I'm attached to one of the process request threads no the mythsocketthread |
| [06:08:23] | andreax (andreax!~andreaz@p57B92E1D.dip.t-dialin.net) has joined #mythtv | |
| [06:08:23] | taylorr: | or am I |
| [06:08:46] | Beirdo: | I'm seeing waiting 101ms for video buffers on the frontend |
| [06:08:51] | Beirdo: | but nothing on the backend at all |
| [06:09:25] | taylorr: | maybe just print the timer always instead of just for above 150 msec |
| [06:09:37] | taylorr: | to see what the time is for each requestblock |
| [06:10:26] | Beirdo: | can do |
| [06:10:37] | taylorr: | Beirdo I think I found another thread |
| [06:10:50] | Beirdo: | K |
| [06:10:51] | taylorr: | it's doing selects and then writes |
| [06:11:07] | taylorr: | is there a thread to handle the socket writes? |
| [06:11:18] | Beirdo: | not sure |
| [06:11:37] | Beirdo: | the simplest way to determine which it is is the backtrace, unfortunately |
| [06:11:48] | Beirdo: | with almost 100 threads in the code... |
| [06:12:28] | Beirdo: | this is very bursty |
| [06:12:39] | Beirdo: | like 10s between bursts of request_blocks |
| [06:13:00] | taylorr: | Beirdo: here is the strace of the mystery thread -> http://mythtv.pastebin.ca/2074008 |
| [06:13:01] | Beirdo: | now 7s |
| [06:14:17] | Beirdo: | that looks like the video data going back to the frontend, not sure what thread that would be |
| [06:14:42] | taylorr: | here is the backtrace |
| [06:14:45] | taylorr: | Thread 1 (process 19473): |
| [06:14:46] | taylorr: | #0 0x00007f7c7f57e85c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0 |
| [06:14:46] | taylorr: | #1 0x00007f7c7d8ac72b in QWaitCondition::wait(QMutex*, unsigned long) () from /usr/lib/libQtCore.so.4 |
| [06:14:46] | taylorr: | #2 0x000000000049eb47 in ?? () |
| [06:14:46] | taylorr: | #3 0x00007f7c7d8ab775 in ?? () from /usr/lib/libQtCore.so.4 |
| [06:14:48] | taylorr: | #4 0x00007f7c7f5799ca in start_thread () from /lib/libpthread.so.0 |
| [06:14:50] | taylorr: | #5 0x00007f7c7cde770d in clone () from /lib/libc.so.6 |
| [06:14:52] | taylorr: | #6 0x0000000000000000 in ?? () |
| [06:15:39] | Beirdo: | well that's not too useful :) |
| [06:15:54] | taylorr: | nope |
| [06:16:11] | taylorr: | I'd like to know where the code is for it though |
| [06:16:19] | Beirdo: | I haven't seen a single request_block over 25ms |
| [06:16:31] | taylorr: | what! |
| [06:16:45] | taylorr: | congratulations |
| [06:16:50] | Beirdo: | oh, there's one at 40ms |
| [06:16:59] | Beirdo: | just to make me a liar. stupid computer ;) |
| [06:17:03] | ** taylorr goes and kicks the server ** | |
| [06:17:13] | andreax (andreax!~andreaz@p57B92E1D.dip.t-dialin.net) has quit (Read error: Connection reset by peer) | |
| [06:17:33] | taylorr: | is your server an i7? |
| [06:17:36] | Beirdo: | and we are on identical versions of qt now |
| [06:17:43] | Beirdo: | i7–850 |
| [06:18:01] | Beirdo: | sorry |
| [06:18:04] | Beirdo: | i7–860 |
| [06:18:07] | Beirdo: | missed :) |
| [06:18:38] | Beirdo: | model name : Intel(R) Core(TM) i7 CPU 860 @ 2.80GHz |
| [06:20:53] | Beirdo: | actually |
| [06:21:00] | Beirdo: | that thread was one of yours |
| [06:21:11] | Beirdo: | i.e. I see a gettid in there |
| [06:21:36] | Beirdo: | line 14 |
| [06:24:13] | taylorr: | ah, so the PRT thread takes care of the socket write? |
| [06:24:53] | taylorr: | weird, now I'm not seeing any request_block delays over 60 |
| [06:25:03] | taylorr: | very strange |
| [06:25:08] | Beirdo: | yeah, the sock->writeData() |
| [06:28:42] | taylorr: | markk: could you try the RequestBlock timer on the backend -> http://mythtv.pastebin.ca/2073992 – not biggie if you don't have time or feel like it |
| [06:29:07] | taylorr: | just wondering what type of delays others are getting |
| [06:29:47] | taylorr: | way past bed time here |
| [06:30:09] | markk: | taylorr: will do – just finishing up the osd stuff. it gives some entertaining info:) |
| [06:30:18] | Beirdo: | on an SD recording, I'm getting < 10ms :) |
| [06:30:49] | Beirdo: | markk: if you run out of fun stuff to do sometime, I'd love to see a "current bitrate" display in the OSD :) |
| [06:30:50] | taylorr: | markk: I'm thinking maybe my backend is just crazy |
| [06:30:52] | Beirdo: | heh |
| [06:30:58] | taylorr: | it has been struck by lightning :) |
| [06:31:09] | Beirdo: | running avg over the last second or whatever |
| [06:31:20] | taylorr: | that's what he's doing now |
| [06:31:27] | Beirdo: | seriously? :) |
| [06:31:29] | Beirdo: | sweet |
| [06:32:19] | markk: | Beirdo: it's coming today:) |
| [06:32:22] | taylorr: | I might swap out my motherboard tomorrow and see if it helps |
| [06:32:43] | Beirdo: | that's so cool. :) |
| [06:32:50] | taylorr: | really going to bed now – I'm too old for this :) |
| [06:32:59] | Beirdo: | night, taylorr :) |
| [06:33:07] | taylorr: | thanks for the help! |
| [06:33:14] | Beirdo: | any time |
| [06:36:42] | Beirdo: | trying moving the threshold in my ringbuffer to bufsize/4 |
| [06:38:28] | danielk22 (danielk22!~danielk@96.57.9.142) has quit (Quit: Leaving.) | |
| [06:39:54] | Beirdo: | what are f in the video buffer wait lines? |
| [06:40:11] | Beirdo: | fAAAAfAALfAAAfLAAf |
| [06:42:05] | Beirdo: | oh wait, I kinda need to make that tweak on the frontend too, don't I? ;) |
| [06:47:45] | Beirdo: | there, let's try that again with the threshold changed on the frontend |
| [06:48:04] | Beirdo: | it's not reading from disk that's the issue, it's the streaming, I'm pretty sure |
| [06:49:46] | jpabq- (jpabq-!~jpabq@174-28-187-116.albq.qwest.net) has quit (Ping timeout: 246 seconds) | |
| [06:51:04] | okolsi: | Beirdo: got a second? |
| [06:51:12] | Beirdo: | sure |
| [06:51:58] | okolsi: | simple path problem with mythgallery/dcraw: http://mythtv.pastebin.ca/2074018 |
| [06:51:58] | jpabq- (jpabq-!~jpabq@174-28-187-116.albq.qwest.net) has joined #mythtv | |
| [06:52:46] | okolsi: | is it okay to just always enclose the path into '' or "" so that paths with spaces work? |
| [06:53:07] | okolsi: | this used to work, not sure when it has broken down |
| [06:53:28] | Beirdo: | it should be OK to put '' around the filepath, yes |
| [06:53:46] | Beirdo: | of course... would be nicer if people wouldn't use spaces in filenames/paths :) |
| [06:54:12] | okolsi: | :D I'll patch it and verify it works again |
| [06:54:14] | Beirdo: | but since that's not always possible to dictate :) |
| [06:54:24] | Beirdo: | sounds good. |
| [06:54:36] | Beirdo: | if it works, I can get that patch in tonight or tomorrow |
| [06:54:40] | okolsi: | k |
| [06:54:49] | Beirdo: | depends how much later I stay up :) |
| [06:55:14] | okolsi: | no hurries, not so many users for dcraw I think.. |
| [06:55:29] | Beirdo: | yeah, I'd bet not. |
| [06:58:53] | Beirdo: | 2011-06–02 23:58:39.604853 RingBuf(myth://Videos@192.168.1.8:6543/test-20110601/test2.mkv): safe_read(...@1310720, 1310720) -> 1310720, took 20 ms (500Mbps) |
| [06:58:57] | Beirdo: | jeez |
| [06:59:01] | Beirdo: | nice having gige |
| [07:02:22] | Beirdo: | taylorr: what's your network speed (just in case it's the remaining variable here)? |
| [07:03:18] | Beirdo: | I think the problem (at least with the BSG clip) is that it's doing a burst of reads every 7–10s |
| [07:03:28] | Beirdo: | and we JUST run out |
| [07:13:06] | Beirdo: | hmm, doubling the buffer size seems to have helped |
| [07:17:38] | okolsi: | Beirdo: #9821 |
| [07:17:43] | Beirdo: | K |
| [07:18:03] | Beirdo: | OMG, the fill threshold is a highwater mark? |
| [07:18:17] | Beirdo: | ummm, yeah, this is lame |
| [07:18:58] | Beirdo: | unless I'm misreading the code, if we are above fill_threshold, we delay 1s |
| [07:19:30] | Beirdo: | I guess that works as long as the fill_threshold level is > 1s of data |
| [07:22:23] | Beirdo: | okolsi: how would you like the credit to read? :) |
| [07:22:47] | Beirdo: | normally, git wants "Name <email>" |
| [07:23:06] | Beirdo: | I have the email from the ticket, would you want the full name in as well? |
| [07:24:54] | okolsi: | Beirdo: just e-mail is fine.. :) |
| [07:25:44] | Beirdo: | K, well, it needs a name of some sorts :) use your IRC nick? |
| [07:26:11] | okolsi: | Beirdo: in that case: "Otto Kolsi" |
| [07:26:26] | Beirdo: | perfect. Thanks |
| [07:33:50] | martin___ (martin___!~quassel@h-67-155.A155.priv.bahnhof.se) has joined #mythtv | |
| [07:51:02] | Beirdo: | well, nearly bed for me |
| [07:58:10] | natanojl (natanojl!~jonatan@c83-252-237-63.bredband.comhem.se) has joined #mythtv | |
| [07:59:54] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Ping timeout: 250 seconds) | |
| [08:00:14] | Gibby_ (Gibby_!~Gibby@204.118.10.244) has joined #mythtv | |
| [08:00:21] | Gibby_ is now known as Gibby | |
| [08:03:37] | okolsi: | markk: with Qt 4.6.3 http://mythtv.pastebin.ca/2074036 other machine with 4.7.2 works fine |
| [08:11:37] | Beirdo: | Hmm, OK, so I stayed up later than I expected. |
| [08:11:46] | Beirdo: | it woudl bug me all night if I didn't |
| [08:12:24] | Beirdo: | markk: For the BSG clip... no glitches at all with the ringbuffer size at 8MB, and the threshold at bufsize/4 |
| [08:13:02] | Beirdo: | even with the super-bursty nature of mkv reads |
| [08:13:43] | Beirdo: | of course, the ringbuffer in the backend has to match that of the frontend |
| [08:17:00] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Ping timeout: 260 seconds) | |
| [08:17:44] | Gibby (Gibby!~Gibby@204.118.10.244) has joined #mythtv | |
| [08:18:08] | wagnerrp: | "omit any nvidia proprietary extentions/additions and just use plain vdpau" |
| [08:18:26] | wagnerrp: | wait... i thought vdpau _was_ nvidia's proprietary extension |
| [08:18:30] | Beirdo: | and on that note, I head for bed. I'm going to try these parameters for a bit |
| [08:18:57] | Beirdo: | wagnerrp: yeah, I don't think the API is necessarily proprietary, but that one made me go whaaa? too |
| [08:19:33] | Beirdo: | night all |
| [08:25:41] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has joined #mythtv | |
| [08:29:28] | MavT (MavT!~MaverickT@dns2.arel.com.au) has joined #mythtv | |
| [08:32:08] | MaverickTech (MaverickTech!~MaverickT@111.86.233.220.static.exetel.com.au) has quit (Ping timeout: 252 seconds) | |
| [08:32:41] | markk: | okolsi: thanks – looks like I need to rethink:) |
| [08:33:29] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Ping timeout: 244 seconds) | |
| [08:34:17] | Gibby (Gibby!~Gibby@204.118.10.244) has joined #mythtv | |
| [08:38:54] | Gibby (Gibby!~Gibby@204.118.10.244) has quit (Ping timeout: 250 seconds) | |
| [09:34:41] | jya (jya!~jyavenard@mythtv/developer/jya) has joined #mythtv | |
| [09:37:04] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has quit (Ping timeout: 246 seconds) | |
| [09:49:25] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has joined #mythtv | |
| [09:57:04] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has quit (Read error: Operation timed out) | |
| [10:05:02] | mike|2 (mike|2!~mike@c-24-21-63-118.hsd1.or.comcast.net) has quit (Remote host closed the connection) | |
| [10:05:54] | mike|2 (mike|2!~mike@c-24-21-63-118.hsd1.or.comcast.net) has joined #mythtv | |
| [10:11:46] | aloril (aloril!~aloril@dsl-tkubrasgw3-fe7ef900-153.dhcp.inet.fi) has joined #mythtv | |
| [10:46:55] | eharris (eharris!~eharris@99-179-7-82.lightspeed.austtx.sbcglobal.net) has quit (Ping timeout: 252 seconds) | |
| [10:48:16] | eharris (eharris!~eharris@99-179-7-82.lightspeed.austtx.sbcglobal.net) has joined #mythtv | |
| [10:50:16] | Kelerion (Kelerion!~Kelerion@131.Red-83-60-249.dynamicIP.rima-tde.net) has joined #mythtv | |
| [10:53:22] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has quit (Remote host closed the connection) | |
| [10:54:14] | cocoa117 (cocoa117!~cocoa117@wk-28-147.guest.rdg.ac.uk) has joined #mythtv | |
| [11:19:34] | martin____ (martin____!~quassel@213.166.186.1) has joined #mythtv | |
| [11:20:06] | martin___ (martin___!~quassel@h-67-155.A155.priv.bahnhof.se) has quit (Ping timeout: 246 seconds) | |
| [11:26:05] | mrand (mrand!~mrand@ubuntu/member/mrand) has quit (Ping timeout: 276 seconds) | |
| [11:45:27] | markk: | hrm – I'm probably missing something – but am I correct in saying that having a larger buffer size won't actually reduce seek times? |
| [11:46:38] | gigem (gigem!~david@mythtv/developer/gigem) has quit (Remote host closed the connection) | |
| [11:47:07] | gigem (gigem!~david@host103.16.intrusion.com) has joined #mythtv | |
| [11:47:07] | gigem (gigem!~david@host103.16.intrusion.com) has quit (Changing host) | |
| [11:47:07] | gigem (gigem!~david@mythtv/developer/gigem) has joined #mythtv | |
| [11:47:09] | markk: | if we seek outside of the buffer, we just discard it and start afresh and the decoder will start producing frames as soon as it has enough data. seeking within a larger buffer should actually be quicker... |
| [11:50:46] | stuartm: | taylorr: fwiw you can set a breakpoint in gdb to do the same thing as an assert but without interupting the program so you can step through from that point etc |
| [11:51:22] | stuartm: | oops, that was in relation to something said 7 hours ago, sorry, didn't notice that I'd left the window scrolled back |
| [11:52:17] | stuartm: | markk: it would have to be a very large buffer to be useful for seeking |
| [11:57:08] | markk: | stuartm: well, 32Mb goes a long way on SD material:) but I'm thinking more along the lines of double our existing default (to 8Mb), plus additional multipliers for networked playback, material of unknown bitrate, variable bitrate, size etc |
| [11:58:22] | markk: | the worst case is the current galactica clip going around that needs a 32Mb buffer (and changes to the fill threshold) to be played over a wifi connection. |
| [12:06:17] | stuartm: | markk: makes sense, certainly better than a one-size-fits-all approach to buffering |
| [12:07:50] | mrand (mrand!~mrand@ubuntu/member/mrand) has joined #mythtv | |
| [12:12:28] | stuartm: | we could ask users to indicate their network speeds during setup from a selection of WiFi 802.11 a/b/g/n and 10/100/1000 ethernet in order to fine tune those multipliers, it's not an unusual thing for applications to ask these days – it's more user friendly than a buffer size setting and more useful too, it can be used to tweak other things too like UI image caching/quality for thumbnail images or on-the-fly transcoding bitrates for upnp etc |
| [12:22:53] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has quit (Read error: Operation timed out) | |
| [12:35:22] | taylorr: | markk: nice work! – do you think the new OSD information is worth adding to the menu? |
| [12:44:15] | taylorr: | markk: interesting observation – if I play a video that does more frequent reads to the backend (~300 msec apart) the latency is very low – it seems only the large spaced reads (ie, once every 20 secs) cause the large delays |
| [12:45:44] | taylorr: | wondering if mythbackend going idle for long periods has a startup cost involved (disk cache getting cleared, etc) |
| [12:46:33] | taylorr: | just guessing but I'll play around more with it to see if we only see the excessive delays with the bursty data transfers |
| [12:49:06] | taylorr: | stuartm: if I set a breakpoint in the code will does gdb get a frozen snapshot of all the threads for the application? |
| [12:49:22] | taylorr: | or just the thread that the breakpoint is triggered? |
| [12:58:41] | danielk22 (danielk22!~danielk@96.57.9.142) has joined #mythtv | |
| [12:58:55] | Jordack (Jordack!~jordack@h69-131-44-221.mdsnwi.tisp.static.tds.net) has joined #mythtv | |
| [13:02:05] | danielk22: | Beirdo: I gave you the wrong variable, fill_min is the one you should change, sorry. |
| [13:04:58] | danielk22: | markk: Increasing the buffer size should not affect seeks negatively and may affect them positively. Post seek reads are only held back based on fill_min being satisfied which is calculated based on the bitrate. |
| [13:05:20] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has joined #mythtv | |
| [13:09:25] | stuartm: | taylorr: all threads |
| [13:09:58] | taylorr: | cool, thanks |
| [13:10:04] | danielk22: | Beirdo: fill_threshold isn't so much a high water mark as a slow down a bit and let other things use the disk mark, it is still supposed eventually fill the buffer. |
| [13:11:52] | zombor (zombor!~zombor_@kohana/developer/zombor) has joined #mythtv | |
| [13:12:02] | danielk22: | Beirdo: But its possible that it doesn't if that generalWait.wait(&rwlock, 1000); is too long which I think it is... 100 – 250 ms might be more appropriate. |
| [13:12:58] | martin___ (martin___!~quassel@h-67-155.A155.priv.bahnhof.se) has joined #mythtv | |
| [13:13:30] | martin____ (martin____!~quassel@213.166.186.1) has quit (Ping timeout: 246 seconds) | |
| [13:17:33] | j-rod|afk is now known as j-rod | |
| [13:19:35] | danielk22: | Ouch, it looks like the long wait puts a hard upper limit on the bitrates we can deal with. :| |
| [13:21:47] | weta is now known as rossand | |
| [13:23:17] | danielk22: | http://pastebin.ca/2074110 <-- should make better use of the buffer we have, untested. |
| [13:24:05] | rossand is now known as weta | |
| [13:35:47] | slipcon (slipcon!~sjlipco@pool-96-255-3-66.washdc.fios.verizon.net) has joined #mythtv | |
| [13:43:53] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has quit (Ping timeout: 276 seconds) | |
| [13:47:50] | taylorr: | danielk22: nice catch |
| [13:49:42] | taylorr: | I think that maybe what's causing the issue with the bursty playback – possibly had nothing to do with the backend response |
| [13:57:18] | danielk22: | taylorr: Well I may be responsible for this one, I think I increased the timeout to 1000 ms without realizing the impact it would have with high bitrate files. |
| [13:58:15] | stuarta: | is the definition of a high bitrate proportional to the available cpu on the frontend? |
| [13:58:47] | stuarta: | ie. would a lower cpu box hit this artificial ceiling on content that a higher cpu box wouldn't hit it on? |
| [13:59:13] | danielk22: | stuarta: it would hit it maybe 5Mbps earlier, but both would hit it. |
| [13:59:57] | stuarta: | i'm wondering cause my lower powered frontend seems to hit some artificial ceiling despite the cpu not being maxed out |
| [14:01:48] | danielk22: | stuarta: you can try my patch or just bump up the buffer size. The hard ceiling is ultimately caused there, but the long timeout was artificially lowering the ceiling to about 1/4 of that. |
| [14:02:04] | taylorr: | danielk22: ok, with that change the readahead thread doesn't get low anymore... but I still get some pauses |
| [14:02:30] | taylorr: | did you review to see if there is any lock contention between the readahead buffer and ReadPriv? |
| [14:05:35] | danielk22: | taylorr: no |
| [14:18:35] | taylorr: | so I've got one matroska cluster read here: 158 x 32 kbyte = ~5 MB and it took 306 msec which is about 135 Mbps |
| [14:19:09] | taylorr: | I'm wondering if an atom just isn't fast enough to parse the data once it's been read |
| [14:19:53] | stuarta: | didn't you say the other day that ffmpeg appears to be the only MKV encoder producing such huge clusters? |
| [14:23:52] | taylorr: | stuarta: from my limited testing it looks like handbrake produced videos which use ffmpeg suffer and I never saw the problem when using MKVtoolnix |
| [14:24:16] | taylorr: | I guess I could remux our sample with mkvmerge and see if it helps |
| [14:26:39] | danielk22: | taylorr: can you try increasing the buffer size as well? Try 16 MB, if that works, try 8 MB. |
| [14:27:36] | taylorr: | danielk22: I'll try, but like I say the readahead is stayring plenty full |
| [14:27:46] | taylorr: | so 8MB or 16MB shouldn't help |
| [14:28:09] | danielk22: | but it's too easy to try to not to.. |
| [14:29:23] | taylorr: | one important note for this particular video is that it's 60fps and VDPAU only provides 17 video buffers – so if it takes more than 250 msec to read/parse the data in the matroska cluster read we will exhaust our video buffers |
| [14:30:21] | taylorr: | compiling with 16MB now |
| [14:34:35] | taylorr: | danielk22: moving to 16MB readahead buffer didn't help |
| [14:35:09] | taylorr: | the only way I've ever resolved this problem is by increasing the vdpaubuffersize to something around 30 |
| [14:35:51] | danielk22: | k, thanks for humoring me. :) |
| [14:35:52] | taylorr: | which provides enough video frames to playback will the decoder is reading packets |
| [14:35:59] | taylorr: | err, while |
| [14:36:36] | taylorr: | trying remuxed video now |
| [14:39:50] | taylorr: | danielk22, markk, Beirdo, stuarta: remuxing the problematic matroska video with MKVToolnix eliminate the burstiness :) |
| [14:40:06] | taylorr: | it appears that ffmpeg is doing something very nasty |
| [14:40:12] | danielk22: | taylorr: make sure you keep the original :) |
| [14:40:41] | taylorr: | no way, I'm tired of this problem already! |
| [14:41:01] | taylorr: | danielk22: I believe you found the biggest problem potentially with that 1 sec sleep |
| [14:43:37] | taylorr: | danielk22: there is also a 250msec wait in WaitForAvail() – any issues with that |
| [14:44:22] | taylorr: | seems excessive – of course the goal is to never hit that condition |
| [14:45:03] | stuartm_ (stuartm_!~stuartm@mythtv/developer/stuartm) has joined #mythtv | |
| [14:45:20] | stuartm (stuartm!~stuartm@mythtv/developer/stuartm) has quit (Ping timeout: 240 seconds) | |
| [14:45:29] | danielk22: | taylorr: that patch should have eliminated the 1 second sleep. the 250ms in waitforavail should not be an issue, we will wake it up as soon as we have the data so it shouldn't really be waiting 250ms unless we have a serious problem reading data.. |
| [14:46:06] | taylorr: | ah, ok, cool |
| [14:46:31] | stuarta: | IMHO, on a philosophical level there should never be any waits where we just sleep for an arbitrary length of time |
| [14:46:52] | stuarta: | but that's just me |
| [14:48:13] | danielk22: | stuarta: that sleep is supposed to only happen when we have nothing to do, and then we are woken up when there is something to do. 1 second was chosen just because it is a "very long time". |
| [14:49:50] | stuartm_ (stuartm_!~stuartm@mythtv/developer/stuartm) has quit (Ping timeout: 250 seconds) | |
| [14:50:13] | danielk22: | It's a "sleep forever, but wake up once in a while just in case we had a coding oversight somewhere" sleep. ;] |
| [14:50:46] | danielk22: | I should mention that it's actually a wait condition that we're calling a sleep. |
| [14:53:27] | danielk22: | hmm, it looks like it's not really breaking the way I thought it was. Even if I make that sleep 5 seconds here the buffer is still filling up. |
| [14:53:43] | stuarta: | yeah, waiting when there's nothing else todo isn't a problem |
| [15:16:21] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has joined #mythtv | |
| [15:18:08] | danielk22: | taylorr: That 1 second sleep isn't really the problem, it gets woken up as soon as the next readpriv finishes. |
| [15:18:40] | taylorr: | danielk22: yes, I just realized we aren't hitting that part of the code anyways |
| [15:19:28] | taylorr: | the "real" problem is that the matroska cluster read can only perform so fast |
| [15:19:30] | danielk22: | yeah, well that is a bug.. there is a missing "!" in front of readsallowed at the start of the if statement. |
| [15:19:43] | taylorr: | hehe |
| [15:20:19] | taylorr: | looks like my one example shows my Atom can process at about 135 Mb/s |
| [15:20:26] | stuartm_ (stuartm_!~stuartm@cpc4-derb9-0-0-cust534.8-3.cable.virginmedia.com) has joined #mythtv | |
| [15:20:26] | stuartm_ (stuartm_!~stuartm@cpc4-derb9-0-0-cust534.8-3.cable.virginmedia.com) has quit (Changing host) | |
| [15:20:26] | stuartm_ (stuartm_!~stuartm@mythtv/developer/stuartm) has joined #mythtv | |
| [15:21:09] | taylorr: | so it takes 300 msec for 5MB and the BSG clip can read several times that amount which makes it take almost 1 second |
| [15:21:44] | taylorr: | so no matter what we due with the readahead buffer my system won't be able to playback without interruption with VDPAU |
| [15:21:55] | taylorr: | since it only uses 17 video buffers |
| [15:22:10] | andreax (andreax!~andreaz@p57B92E1D.dip.t-dialin.net) has joined #mythtv | |
| [15:25:13] | abqjp (abqjp!~abqjp@97-119-171-42.albq.qwest.net) has joined #mythtv | |
| [15:35:09] | sphery: | markk: haven't caught up with commits, so you may have "fixed" it already, but regardign QDateTime::msecsTo() being added in Qt 4.7, I know that there were some other places that people were wanting to use that, and may be some other Qt 4.7 features that could be useful. Don't know if it's still too early to consider requiring Qt 4.7, though(, but if not, maybe we should consider it). |
| [15:35:53] | stuarta: | sphery: we should keep an eye on what is in the stable versions of each distro and ideally not go beyond that |
| [15:36:21] | stuarta: | for example debian stable has 4.6.3 |
| [15:37:09] | stuarta: | and that came out on 19th March 2011 |
| [15:40:31] | markk: | sphery: 4.7 would be nice for a couple of reasons, but it was only an issue because I recently forced that dev box to 4.7 for some QNetwork stuff that I needed to test upnp scanning. At least 2 of my boxes don't 'officially' support 4.7 yet. |
| [15:41:23] | taylorr: | markk: I still believe that we will need more video buffers for vdpau playback of these matroska videos |
| [15:41:39] | danielk22: | taylorr: I just pushed a few RingBuffer fixes to master, but unfortunately they won't help you any. |
| [15:44:40] | taylorr: | markk: did you see my comment about remuxing the matroska with MKVtoolnix eliminates the burstiness |
| [15:44:50] | stoffel (stoffel!~quassel@p57B4CAF7.dip.t-dialin.net) has quit (Ping timeout: 240 seconds) | |
| [15:44:52] | taylorr: | even the BSG clip plays back fine after remuxing :) |
| [15:45:20] | markk: | taylorr: it's a compromise about where the buffering takes place. video memory is a scarce resource for some, whereas another 8–16Mb of main memory isn't a great deal. and increasing the video buffer size has implications for certain aspects of video playback. |
| [15:45:21] | danielk22: | Beirdo: ^^ I increased the fill_threshold to 3/4 of the buffer, and re-enabled the long sleep which I believe I disabled in a botched merge :| The fill_threshold was essentially being ignored anyway and we were always keeping the buffer full so my theorizing earlier today can be fully ignored. |
| [15:46:01] | markk: | taylorr: but we can't expect people to remux their files:) |
| [15:46:30] | taylorr: | markk: actually it's no compromise for the situation where we are doing a matroska cluster read and it takes 300 msec to 1 sec – we need more video buffers for that, right? |
| [15:46:53] | danielk22: | The upshot is the RingBuffer should now be using less CPU, but todays changes will have no effect on taylor's problem. |
| [15:47:37] | markk: | taylorr: it's not going to take 300msec to 1 sec if it's already buffered. |
| [15:47:49] | taylorr: | markk: um, but it does |
| [15:48:22] | taylorr: | that's how long it takes for my atom to read,parse,buffer inside ffmpeg |
| [15:48:39] | taylorr: | the reads from the ringbuffer are sufficiently fast |
| [15:49:08] | taylorr: | it's doing it at 135 Mbs which I don't think is necessarily slow |
| [15:49:30] | danielk22: | The more I learn about the atom the less I like it.. reminds me of the VIA processors. |
| [15:49:41] | taylorr: | danielk22: your changes "may" help a little |
| [15:50:03] | taylorr: | if you put the readahead asleep it allows the reads from the buffer to be faster |
| [15:50:23] | stuarta: | most of the atom boards combine with a decent gpu |
| [15:55:34] | gigem (gigem!~david@mythtv/developer/gigem) has quit (Remote host closed the connection) | |
| [15:56:00] | gigem (gigem!~david@host103.16.intrusion.com) has joined #mythtv | |
| [15:56:00] | gigem (gigem!~david@host103.16.intrusion.com) has quit (Changing host) | |
| [15:56:00] | gigem (gigem!~david@mythtv/developer/gigem) has joined #mythtv | |
| [16:01:47] | markk: | danielk22: I'm still not sure what the purpose of fill_threshold is. on these bursty files, during periods when the decoder is not reading data, the buffer sits at 70–80% full when we could be pulling in more data. |
| [16:02:43] | markk: | (70–80% full with your latest change) |
| [16:07:13] | kormoc is now known as kormoc_afk | |
| [16:21:10] | stuartm_ is now known as stuartm | |
| [16:21:33] | stuartm: | there's no reason not to fill the buffer? |
| [16:23:54] | stuartm: | stuarta: it's true they tend to ship with decent graphics but I think what's been slowly revealed about the actual performance of the Atom and the corner's they cut to get those headline grabbing wattage figures has left a lot of people with a sense of buyers remorse |
| [16:24:52] | stuartm: | s/corner's/corners/ |
| [16:25:14] | stuartm: | s/buyers/buyer's/ |
| [16:25:36] | markk: | taylorr: I'll have another look at vdpau/ion performance in the morning. Ideally with a slowish wifi connection... (for absolute worst case). |
| [16:25:44] | markk: | but now sleep:) |
| [16:27:14] | stuartm: | just a year ago everyone here was pretty excited about the atom and it seemed everyone was racing out to buy Atom based small form-factor devices to operate as frontends, now it seems we're advising that they are unsuitable for both frontend and backend use |
| [16:27:40] | taylorr: | markk: make sure you are using a minimum number of vdpau video buffers too :) |
| [16:27:45] | stuartm: | it's quite a turn around |
| [16:28:12] | taylorr: | I like my ION |
| [16:29:07] | taylorr: | the video side works remarkably well... but I agree the Atom side of it isn't all that impressive |
| [16:29:17] | taylorr: | except for the power savings, of course |
| [16:29:58] | taylorr: | markk: I don't to find out everything played back fine for you and you had you vdpau buffer size set to 100! :) |
| [16:30:23] | taylorr: | especially when 50 is the max |
| [16:30:28] | Beirdo: | danielk22: nice. I'll retest with your changes tonight. I think changing the buffer to 8MB still could be in order for some of the higher bitrate stuff out there |
| [16:30:52] | Beirdo: | especially if it's a bursty mkv file |
| [16:31:03] | Beirdo: | heh. Anyways, I should get to work |
| [16:32:30] | SteveGoodey (SteveGoodey!~steve@host109-158-215-171.range109-158.btcentralplus.com) has joined #mythtv | |
| [16:45:29] | gigem (gigem!~david@mythtv/developer/gigem) has quit (Remote host closed the connection) | |
| [16:45:58] | gigem (gigem!~david@host103.16.intrusion.com) has joined #mythtv | |
| [16:45:58] | gigem (gigem!~david@host103.16.intrusion.com) has quit (Changing host) | |
| [16:45:58] | gigem (gigem!~david@mythtv/developer/gigem) has joined #mythtv | |
| [17:02:24] | kormoc_afk is now known as kormoc | |
| [17:17:05] | mrand (mrand!~mrand@ubuntu/member/mrand) has quit (Ping timeout: 246 seconds) | |
| [17:17:57] | mrand (mrand!~mrand@ubuntu/member/mrand) has joined #mythtv | |
| [17:37:14] | jarle (jarle!~jarle@70.84-234-133.customer.lyse.net) has quit (Remote host closed the connection) | |
| [17:47:13] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has joined #mythtv | |
| [17:53:08] | SteveGoodey (SteveGoodey!~steve@host109-158-215-171.range109-158.btcentralplus.com) has quit (Ping timeout: 250 seconds) | |
| [17:53:12] | Steve_Goodey (Steve_Goodey!~steve@host86-147-81-27.range86-147.btcentralplus.com) has joined #mythtv | |
| [17:53:13] | Steve_Goodey (Steve_Goodey!~steve@host86-147-81-27.range86-147.btcentralplus.com) has quit (Remote host closed the connection) | |
| [18:26:35] | danielk22: | markk: I considered removing fill_threshold when I fixed up the locking in the [File]RingBuffer code. |
| [18:26:40] | danielk22: | I believe the idea is that you want to back off on disk reads when you have enough buffering for fairness to other processes wanting to do IO + You also want to try to decouple the many small reads ffmpeg does from actual disk reads so you don't do a lot of 32KB reads when you could be doing 512KB reads. |
| [18:27:31] | danielk22: | I don't think the decoupling really works with the current implementation, but it does allow other processes to do IO. |
| [18:36:30] | stuartm: | wouldn't they still be able to do that IO when we slow reading because the buffer is at 100%? Or is reaching 100% such a rare event that we'd be permanently blocking? |
| [19:22:44] | cocoa117 (cocoa117!~cocoa117@wk-28-147.guest.rdg.ac.uk) has quit (Quit: Leaving) | |
| [19:23:07] | wgwinn (wgwinn!~chatzilla@c-68-36-58-132.hsd1.nj.comcast.net) has joined #mythtv | |
| [19:26:34] | sphery (sphery!~mdean@mythtv/developer/sphery) has quit (Read error: Connection reset by peer) | |
| [19:27:42] | sphery (sphery!~mdean@mythtv/developer/sphery) has joined #mythtv | |
| [19:43:35] | danielk22: | stuartm: Hitting 100% is a very rare event. But when we read from disk we're actually reading from the cache most of the time, so it's not as if we're swinging the hard drive heads away from a DB update so we can service a disk read. |
| [19:48:22] | Goga777 (Goga777!~Goga777@shpd-92-101-153-118.vologda.ru) has quit (Remote host closed the connection) | |
| [19:49:21] | danielk22: | stuartm: The ring buffer exists for disks only because the OS doesn't do a good enough job buffering itself, but the OS still does do some buffering. When streaming from a backend we're actually 3 buffers removed from the hardware. |
| [19:57:54] | danielk22: | markk: On my system — NFS over wifi: Storage to Buffer: >1Gbps, Buffer to decoder 6–9.4Mbps, Available buffer: 89–99% |
| [19:57:54] | danielk22: | MythStreaming over wifi: Storage to Buffer: 25Mbps, Buffer to decoder: 2–2.4Mbps, Available buffer: 91–99% (I don't have the MKV this is with 1080i recordings I have). |
| [19:59:46] | danielk22: | BTW The video plays fine and the overall bitrate is 7.45Mbps so there may be something off with the buffer to decoder bitrate reporting. |
| [20:12:17] | taylorr: | Beirdo, wagnerrp: for VERBOSE calls do we immediately flush to the log file? |
| [20:12:39] | Beirdo: | in master, yes |
| [20:12:50] | Beirdo: | in new-logging, no |
| [20:12:53] | taylorr: | hmmmm, isn't that inefficient |
| [20:12:59] | Beirdo: | definitely |
| [20:13:09] | taylorr: | does it flush in 0.24-fixes? |
| [20:13:32] | taylorr: | I'm thinking that maybe why I have such slowness with logging turned on |
| [20:13:45] | Beirdo: | yeah, it's syncronous in 0.24-fixes as well |
| [20:14:00] | Beirdo: | as in, you are waiting for it to write to disk and to console |
| [20:14:06] | taylorr: | Beirdo: is it easy to disable the flushing for 0.24-fixes? |
| [20:14:35] | taylorr: | oh yeah, that's write, it has to go to the screen if we are tailing it |
| [20:14:37] | Beirdo: | not that I know of, that's default behavior with cout<< |
| [20:14:45] | Beirdo: | or cerr<< |
| [20:14:51] | Beirdo: | forget which is in use |
| [20:15:10] | taylorr: | so we don't setup the PIPE for cout? |
| [20:15:36] | Beirdo: | not that I know of |
| [20:18:48] | danielk22: | Beirdo: taylorr: We don't sync so the file doesn't actually need to be written to disk on each write; just visible to the OS. |
| [20:20:29] | Beirdo: | ah, true, but the console is still synchronous |
| [20:21:35] | danielk22: | sure, but that isn't the usual case. hmm, taylor are your time measurements made with the logging sent to a console or terminal? |
| [20:22:33] | taylorr: | danielk22: I usually write to a log and then tail the logfile... but even if I'm not tailing the logfile it's slow |
| [20:31:35] | danielk22: | taylorr: the "tail -f" would mean that there is always at least two processes contending for the processor after a verbose macro.. the "tail -f" and then the konsole/xterm will want to redraw after tail -f adds text. |
| [20:33:36] | taylorr: | I'm also using ext4, I wonder if that could be an issue |
| [20:33:49] | taylorr: | I might point my logfile to a different disk and see if it helps any |
| [20:34:03] | taylorr: | I have one disk that is ext3 and one that is xfs |
| [20:36:41] | danielk22: | taylorr: I doubt it. AFAIK ext4 performance problems are only with barriers like fsync(), there is a flush but no sync in the VERBOSE case. |
| [20:36:59] | danielk22: | + you'd be seeing worse than 10ms delays :) |
| [20:41:50] | taylorr: | danielk22: if I I run with the -v options but omit the --logfile option there is no slowdown |
| [20:42:44] | taylorr: | I'm running via init.d so I have no idea where the VERBOSE output is going :) |
| [20:44:37] | kormoc: | taylorr, you can tryp setting ext3's commit higher, it defaults to 5 seconds. you could set it to a few minutes and see if it'd help (it limits how long data can be in memory before being synced to disk) |
| [20:44:41] | danielk22: | taylorr: hehe, I dunno either but the I think important thing is your not looking at it so the Heisenberg principle is not effect. ;] I assume the actual problem still exist though. |
| [20:46:53] | taylorr: | danielk22: I'm hoping this is some system issue that only applies to me.. maybe my disk controller/actual disk or something has an issue |
| [20:48:42] | fphillips (fphillips!~fp@adsl-71-145-161-95.dsl.austtx.sbcglobal.net) has joined #mythtv | |
| [21:09:45] | cocoa117 (cocoa117!~cocoa117@188-222-31-239.zone13.bethere.co.uk) has joined #mythtv | |
| [21:13:16] | martin___ (martin___!~quassel@h-67-155.A155.priv.bahnhof.se) has quit (Remote host closed the connection) | |
| [21:16:29] | taylorr: | danielk22: sending the logfile to another drive fixes the issue |
| [21:16:41] | taylorr: | must be something with ext4 or the hardware itself |
| [21:18:39] | danielk22: | taylorr: but when you first had the problem I'm assuming you didn't have a lot of logging going on, right? |
| [21:23:51] | slipcon (slipcon!~sjlipco@pool-96-255-3-66.washdc.fios.verizon.net) has quit (Quit: Leaving.) | |
| [21:25:21] | cocoa117 (cocoa117!~cocoa117@188-222-31-239.zone13.bethere.co.uk) has quit (Remote host closed the connection) | |
| [21:27:25] | danielk22: | markk: http://www.pastebin.ca/2074278 <- one potential fix for the bitrate calc. The assumed the range of the samples was one second but an average of 1.5 samples were dropped from that range. The new sample was added after summing plus the oldest sample wont be at exactly 1000 ms before the new sample. |
| [21:30:21] | cocoa117 (cocoa117!~cocoa117@188-222-31-239.zone13.bethere.co.uk) has joined #mythtv | |
| [21:45:49] | analogue_ (analogue_!~analogue@c-98-222-42-225.hsd1.il.comcast.net) has quit (Ping timeout: 252 seconds) | |
| [21:54:53] | j-rod is now known as j-rod|afk | |
| [22:03:19] | analogue_ (analogue_!~analogue@c-98-222-42-225.hsd1.il.comcast.net) has joined #mythtv | |
| [22:20:47] | natanojl (natanojl!~jonatan@c83-252-237-63.bredband.comhem.se) has quit (Ping timeout: 240 seconds) | |
| [22:20:53] | stuartm: | I saw a new error message last night that made me laugh, it was something along the line of "This recording was missed because the backend was either offline or hung" |
| [22:21:55] | stuartm: | "or hung" signals defeat, but it also happened to be true in this case, the backend was hung but sadly not running under gdb for the first time in three weeks |
| [22:33:00] | Beirdo: | heh |
| [22:40:10] | Dave123-road (Dave123-road!~dave@cpe-74-74-200-106.rochester.res.rr.com) has quit (Ping timeout: 248 seconds) | |
| [22:43:57] | Dave123-road (Dave123-road!~dave@cpe-74-74-200-106.rochester.res.rr.com) has joined #mythtv | |
| [22:44:01] | Beirdo: | danielk22: any chance of increasing the buffer size to 8MB as well? |
| [22:44:41] | Beirdo: | (I have yet to test with your changes, but it seems that a bigger buffer may be a good plan for surviving massively changing bitrates) |
| [22:49:44] | gigem: | stuartm: sorry to hear you missed a recording, but i'm glad to hear the missed recording logic worked in the real world. btw, if you've got a better suggestion for "hung", please offer it. "inoperable" is the best that comes to mind atm, but it's just as defeatist. |
| [22:50:15] | laga: | "well hung" sounds a bit more positive. /me goes back into hiding |
| [22:51:59] | stuartm: | gigem: I've no problem with "hung", it's accurate and a widely used term |
| [22:53:24] | stuartm: | I wish it wasn't necessary to even suggest it as a reason for the failure, but sadly the backend does still hang for one reason or another :) |
| [22:55:12] | gigem: | i suppose we could drop the "or hung" part and just leave it as offline. in a sense, part of the backend *is* offline when it is hung. |
| [22:55:35] | stuartm: | I'm not really trying hard enough to figure out the reason for the hang I keep seeing, I need to be more proactive and finally get a backtrace |
| [23:00:40] | stuartm: | gigem: it really did make me smile though, it reminded me of an error I once saw a store website display "Sorry, we cannot take your order right now, the database has probably crashed again" |
| [23:49:02] | cocoa117 (cocoa117!~cocoa117@188-222-31-239.zone13.bethere.co.uk) has quit (Quit: Leaving) | |
| [23:50:13] | abqjp (abqjp!~abqjp@97-119-171-42.albq.qwest.net) has quit (Quit: abqjp) | |
| [23:58:57] | taylorr: | danielk22: the problem was that I mistook the additional VERBOSE calls causing delays as a backend ringbuffer performance problem – once I turned off logging the backend seems to work fine – I have had performance issue with logs turned on ever since I upgraded my machine and switched to ext4 |
| [23:59:12] | danielk22: | Beirdo: I'm not going to do it until there is an example of it making a difference for someone. |
| [23:59:41] | taylorr: | danielk22: I believe the BSG video needs at least 8MB |
| [23:59:50] | taylorr: | did you download that one yet? |
IRC Logs collected by
BeirdoBot.
Please use the above link to report any bugs.