[mythtv-users] RingBuf(...): Waited 0.2 seconds for data to become available...
Brian J. Murrell
brian at interlinx.bc.ca
Thu Feb 16 11:49:32 UTC 2012
Running master (v0.25pre-4525-gdcfe7b0) I am seeing the following in
the BE log:
/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 130964 < 131072
2012-02-16 02:11:11.071747 I [29229/20156] ProcessRequest ringbuffer.cpp:1093 (WaitForAvail) - RingBuf(/video/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 121884 < 131072
2012-02-16 02:11:23.645359 I [29229/20156] ProcessRequest ringbuffer.cpp:1093 (WaitForAvail) - RingBuf(/video/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 127488 < 131072
2012-02-16 02:11:28.380541 I [29229/20156] ProcessRequest ringbuffer.cpp:1093 (WaitForAvail) - RingBuf(/video/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 128792 < 131072
2012-02-16 02:12:25.619496 I [29229/20156] ProcessRequest ringbuffer.cpp:1093 (WaitForAvail) - RingBuf(/video/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 60412 < 98304
2012-02-16 02:12:37.692135 I [29229/20156] ProcessRequest ringbuffer.cpp:1093 (WaitForAvail) - RingBuf(/video/mythtv/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 89716 < 98304
And similar in the mythjobqueue log running on another machine (to do
commflagging):
2012-02-16 02:11:04.158075 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:11:16.868111 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:11:33.427089 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:11:35.918127 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:11:37.414111 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:12:28.619130 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:12:31.226079 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
2012-02-16 02:12:43.227096 I RingBuf(myth://10.75.22.2:6543/4112_20120216020000.mpg): Waited 0.2 seconds for data
to become available... 0 < 32768
This happens during every recording window, even when there is just a
single recording happening as there was from 02:00:00-03:00:00 this morning.
But you can see that resources seem to be plentiful -- or at least
quite sufficient during that time:
01:35:01 AM CPU %user %nice %system %iowait %steal %idle
01:45:01 AM all 0.42 0.00 0.20 0.05 0.00 99.33
01:55:01 AM all 0.42 0.00 0.18 0.02 0.00 99.38
02:05:01 AM all 4.81 0.37 4.00 2.79 0.00 88.03
02:15:01 AM all 9.32 0.00 8.83 3.72 0.00 78.13
02:25:02 AM all 17.94 0.00 20.74 3.26 0.00 58.05
02:35:01 AM all 15.85 0.00 17.35 3.32 0.00 63.47
02:45:01 AM all 8.93 0.00 6.43 3.96 0.00 80.68
02:55:01 AM all 8.85 0.00 6.44 4.40 0.00 80.31
03:05:02 AM all 9.72 0.08 5.97 4.71 0.00 79.53
03:15:01 AM all 0.14 0.00 0.15 0.18 0.00 99.54
03:25:01 AM all 0.42 0.00 0.18 0.02 0.00 99.37
Average: all 6.96 0.04 6.38 2.40 0.00 84.22
01:35:01 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
01:45:01 AM dev252-19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
01:55:01 AM dev252-19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
02:05:01 AM dev252-19 58.12 0.03 464.93 8.00 0.26 4.48 0.35 2.02
02:15:01 AM dev252-19 115.05 0.09 920.32 8.00 0.50 4.38 0.39 4.51
02:25:02 AM dev252-19 110.87 0.03 886.92 8.00 0.51 4.59 0.42 4.67
02:35:01 AM dev252-19 106.12 0.04 848.91 8.00 0.46 4.30 0.43 4.58
02:45:01 AM dev252-19 110.24 0.04 881.84 8.00 0.46 4.16 0.42 4.68
02:55:01 AM dev252-19 111.07 0.09 888.44 8.00 0.48 4.36 0.44 4.92
03:05:02 AM dev252-19 58.43 11.81 466.38 8.18 0.27 4.58 0.46 2.68
03:15:01 AM dev252-19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:25:01 AM dev252-19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
Average: dev252-19 60.79 1.11 486.21 8.02 0.27 4.39 0.42 2.55
01:35:01 AM tps rtps wtps bread/s bwrtn/s
01:45:01 AM 0.76 0.01 0.74 0.13 5.52
01:55:01 AM 0.67 0.10 0.58 1.24 4.58
02:05:01 AM 79.82 9.65 70.16 90.90 1000.74
02:15:01 AM 133.55 1.42 132.13 12.19 1930.16
02:25:02 AM 422.60 17.66 404.94 193.22 2966.28
02:35:01 AM 424.59 2.22 422.37 22.47 2971.55
02:45:01 AM 127.14 0.06 127.07 0.59 1852.18
02:55:01 AM 130.00 1.31 128.69 11.15 1871.55
03:05:02 AM 131.94 61.18 70.76 652.10 1021.65
03:15:01 AM 6.85 6.22 0.63 67.87 4.76
03:25:01 AM 0.83 0.13 0.70 0.82 5.34
Average: 131.96 9.09 122.87 95.68 1235.58
01:35:01 AM pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff
01:45:01 AM 0.03 0.94 15.60 0.00 4.02 0.00 0.00 0.00 0.00
01:55:01 AM 0.30 0.77 9.31 0.01 1.92 0.00 0.00 0.00 0.00
02:05:01 AM 15.88 244.64 63.47 0.18 133.76 0.00 0.00 0.00 0.00
02:15:01 AM 2.06 475.10 10.40 0.06 357.91 82.15 0.00 81.91 99.70
02:25:02 AM 32.50 732.93 350.01 0.35 775.92 98.42 0.00 97.55 99.11
02:35:01 AM 3.78 735.22 294.03 0.05 463.71 0.00 0.00 0.00 0.00
02:45:01 AM 0.13 455.73 9.42 0.00 279.55 26.63 0.00 25.59 96.12
02:55:01 AM 1.97 460.07 2.79 0.05 362.29 107.33 0.00 106.81 99.52
03:05:02 AM 112.42 250.16 43.93 0.87 445.01 182.57 0.00 177.51 97.23
03:15:01 AM 11.41 0.80 16.02 0.15 4.03 0.00 0.00 0.00 0.00
03:25:01 AM 0.14 0.90 11.49 0.00 2.62 0.00 0.00 0.00 0.00
Average: 16.42 304.24 74.58 0.16 256.53 45.19 0.00 44.48 98.44
01:35:01 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact
01:45:01 AM 269952 1272460 82.50 35324 989668 786664 38.06 580292 548708
01:55:01 AM 269704 1272708 82.51 35440 989688 786664 38.06 580628 548684
02:05:01 AM 103460 1438952 93.29 39240 1129628 878328 42.50 723644 568388
02:15:01 AM 34892 1507520 97.74 43260 1195772 878592 42.51 749548 613020
02:25:02 AM 459168 1083244 70.23 45176 768188 895124 43.31 631924 304904
02:35:01 AM 228096 1314316 85.21 52980 994664 876408 42.41 810040 360152
02:45:01 AM 36092 1506320 97.66 52312 1187264 876408 42.41 901312 460880
02:55:01 AM 36340 1506072 97.64 18032 1222148 876408 42.41 808912 553996
03:05:02 AM 282160 1260252 81.71 13360 1004248 786664 38.06 564876 555972
03:15:01 AM 275488 1266924 82.14 13564 1010900 786664 38.06 565592 562276
03:25:01 AM 275356 1267056 82.15 13716 1010984 786664 38.06 565688 562416
Average: 206428 1335984 86.62 32946 1045741 837690 40.53 680223 512672
I think what is obvious above is that all disk reading was satisfied by
the cache and the CPU was not under stress so there's really no
resourceful reason that there should be excessive delays. I wonder if
there is something else lurking in the code that is introducing delay.
Or maybe such delays are normal and expected, but then I'd think it's
not worth constantly printing messages about them.
Thoughts?
b.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 262 bytes
Desc: OpenPGP digital signature
Url : http://www.mythtv.org/pipermail/mythtv-users/attachments/20120216/6c4cd7d0/attachment.bin
More information about the mythtv-users
mailing list