[mythtv-users] recent "TFW -- took a long time" warnings

[Warpme]

On 5/31/12 9:50 PM, Warpme wrote:
> Hi*
>
> Recently our BE starts to have regularly report about delays in TFW:
>
> 2012-05-31 19:00:12.405548 W 
> TFW(/myth/tv/23809_20120531190000.mpg:50): write(57528) cnt 55 total 
> 3175696 -- took a long time, 2507 ms
> 2012-05-31 19:00:12.450454 W TFW(/myth/tv/9071_20120531185000.mpg:76): 
> write(57716) cnt 7 total 389912 -- took a long time, 1400 ms
> 2012-05-31 19:15:20.906030 W 
> TFW(/myth/tv/21109_20120531191500.mpg:58): write(57528) cnt 12 total 
> 653300 -- took a long time, 1113 ms
> 2012-05-31 20:05:10.326524 W 
> TFW(/myth/tv/23809_20120531200500.mpg:51): write(57716) cnt 50 total 
> 2861548 -- took a long time, 2885 ms
> 2012-05-31 21:05:11.311221 W TFW(/myth/tv/8105_20120531210500.mpg:51): 
> write(57716) cnt 19 total 1047912 -- took a long time, 1221 ms
>
> It started week or two ago - but I can't correlate it with anything 
> special regarding my HW or SW.
> HW was untouched and SW in as well beside routinely upgraded mythtv 
> (build every week or two).
> Initially I suspect failing HDD so I replaced HDD with /myth volume to 
> new one.
> OS+DB HDD remains untouched.
> What surprise when after installing new shiny 3TB WD green I still see 
> those errors.
> So my question is: where issue might be ?
> Do anybody have idea how to nail down root cause of those errors.
> What interesting - system works OK (I don't observe any anomalies).
>
>
> some details:
> v0.25-128-ga9edae2-dirty-20120529, archlinux, kernel 3.3.7, 1st HDD WD 
> Green 2TB with OS/DB, 2nd WD Green 3TB with myth vol.
>
> -br
>
>
>
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://www.mythtv.org/mailman/listinfo/mythtv-users
I'm continuing my investigation.
I stop all services/daemons in system (only BE is running) and launch 
stress test: 8xHD + 4xSD recordings + 4xCommflager concurrently for 4h.
Results are like blow.
I see here that TFW errors are consolidated & only in short points in time.
Interesting...

2012-06-01 13:04:57.322177 W TFW(/myth/tv/23711_20120601120000.mpg:121): 
write(57528) cnt 82 total 4700000 -- took a long time, 3909 ms
2012-06-01 13:04:57.326113 W TFW(/myth/tv/8047_20120601120100.mpg:269): 
write(57716) cnt 35 total 2032092 -- took a long time, 3893 ms
2012-06-01 13:04:57.326761 W TFW(/myth/tv/21020_20120601120000.mpg:134): 
write(57528) cnt 64 total 3687808 -- took a long time, 3907 ms
2012-06-01 13:04:57.331946 W TFW(/myth/tv/21026_20120601120000.mpg:52): 
write(57528) cnt 80 total 4616340 -- took a long time, 4868 ms
2012-06-01 13:04:57.355266 W TFW(/myth/tv/22900_20120601120100.mpg:147): 
write(57528) cnt 30 total 1724524 -- took a long time, 3922 ms
2012-06-01 13:04:57.355346 W TFW(/myth/tv/13108_20120601120000.mpg:54): 
write(57528) cnt 38 total 2170836 -- took a long time, 3962 ms
2012-06-01 13:04:57.357338 W TFW(/myth/tv/9073_20120601120100.mpg:223): 
write(62980) cnt 36 total 2047132 -- took a long time, 3900 ms
2012-06-01 13:04:57.365550 W TFW(/myth/tv/21023_20120601120100.mpg:192): 
write(57716) cnt 41 total 2338720 -- took a long time, 3918 ms
2012-06-01 13:04:57.371875 W TFW(/myth/tv/22901_20120601120100.mpg:205): 
write(57904) cnt 30 total 1724712 -- took a long time, 3938 ms
2012-06-01 13:04:57.372827 W TFW(/myth/tv/9075_20120601120100.mpg:241): 
write(57528) cnt 22 total 1281596 -- took a long time, 3876 ms
2012-06-01 13:04:57.372964 W TFW(/myth/tv/9072_20120601120100.mpg:227): 
write(57716) cnt 25 total 1463580 -- took a long time, 3959 ms
2012-06-01 13:04:57.380554 W TFW(/myth/tv/9071_20120601120100.mpg:215): 
write(57528) cnt 26 total 1477492 -- took a long time, 3945 ms
2012-06-01 13:05:20.503503 W TFW(/myth/tv/23711_20120601120000.mpg:121): 
write(57528) cnt 194 total 11191828 -- took a long time, 7091 ms
2012-06-01 13:05:20.503649 W TFW(/myth/tv/21020_20120601120000.mpg:134): 
write(57904) cnt 133 total 7670588 -- took a long time, 7080 ms
2012-06-01 13:05:20.504498 W TFW(/myth/tv/21023_20120601120100.mpg:192): 
write(57528) cnt 83 total 4783096 -- took a long time, 8091 ms
2012-06-01 13:05:20.617680 W TFW(/myth/tv/22901_20120601120100.mpg:205): 
write(57528) cnt 79 total 4544900 -- took a long time, 7200 ms
2012-06-01 13:05:20.622491 W TFW(/myth/tv/21026_20120601120000.mpg:52): 
write(57904) cnt 88 total 5077316 -- took a long time, 7122 ms
2012-06-01 13:05:20.622870 W TFW(/myth/tv/9073_20120601120100.mpg:223): 
write(57528) cnt 63 total 3633100 -- took a long time, 7241 ms
2012-06-01 13:05:20.623720 W TFW(/myth/tv/13108_20120601120000.mpg:54): 
write(57904) cnt 74 total 4259516 -- took a long time, 7218 ms
2012-06-01 13:05:20.629834 W TFW(/myth/tv/9071_20120601120100.mpg:215): 
write(57528) cnt 48 total 2799696 -- took a long time, 7087 ms
2012-06-01 13:05:20.634068 W TFW(/myth/tv/8047_20120601120100.mpg:269): 
write(58092) cnt 70 total 4065124 -- took a long time, 7173 ms
2012-06-01 13:05:20.634435 W TFW(/myth/tv/22900_20120601120100.mpg:147): 
write(57716) cnt 65 total 3735936 -- took a long time, 7208 ms
2012-06-01 13:05:20.637574 W TFW(/myth/tv/9072_20120601120100.mpg:227): 
write(58280) cnt 46 total 2649296 -- took a long time, 7141 ms
2012-06-01 13:05:20.645510 W TFW(/myth/tv/9075_20120601120100.mpg:241): 
write(57904) cnt 36 total 2096012 -- took a long time, 7095 ms
2012-06-01 13:13:07.499148 W TFW(/myth/tv/8047_20120601120100.mpg:269): 
write(57904) cnt 529 total 30629336 -- took a long time, 33004 ms
2012-06-01 13:13:07.499240 W TFW(/myth/tv/21023_20120601120100.mpg:192): 
write(57528) cnt 537 total 31011916 -- took a long time, 33043 ms
2012-06-01 13:13:07.504513 W TFW(/myth/tv/21020_20120601120000.mpg:134): 
write(57528) cnt 553 total 31947404 -- took a long time, 33076 ms
2012-06-01 13:13:07.508678 W TFW(/myth/tv/23711_20120601120000.mpg:121): 
write(57716) cnt 387 total 22366924 -- took a long time, 33030 ms
2012-06-01 13:13:07.670861 W TFW(/myth/tv/21026_20120601120000.mpg:52): 
write(57716) cnt 314 total 18193700 -- took a long time, 33096 ms
2012-06-01 13:13:07.670914 W TFW(/myth/tv/22901_20120601120100.mpg:205): 
write(57716) cnt 508 total 29334204 -- took a long time, 33187 ms
2012-06-01 13:13:07.670944 W TFW(/myth/tv/22900_20120601120100.mpg:147): 
write(57528) cnt 342 total 19727216 -- took a long time, 33164 ms
2012-06-01 13:13:07.697865 W TFW(/myth/tv/9075_20120601120100.mpg:241): 
write(57716) cnt 260 total 15088128 -- took a long time, 33137 ms
2012-06-01 13:13:07.705433 W TFW(/myth/tv/9071_20120601120100.mpg:215): 
write(65236) cnt 214 total 12450864 -- took a long time, 33245 ms
2012-06-01 13:13:07.713315 W TFW(/myth/tv/9073_20120601120100.mpg:223): 
write(48504) cnt 164 total 9603792 -- took a long time, 33152 ms
2012-06-01 13:13:07.806253 W TFW(/myth/tv/9072_20120601120100.mpg:227): 
write(57716) cnt 218 total 12708236 -- took a long time, 33315 ms
2012-06-01 13:13:07.866150 W TFW(/myth/tv/13108_20120601120000.mpg:54): 
write(57904) cnt 492 total 28479744 -- took a long time, 33342 ms
2012-06-01 14:00:50.547382 W TFW(/myth/tv/9071_20120601120100.mpg:215): 
Taking a long time to flush.. buffer size 0


-------------- next part --------------
A non-text attachment was scrubbed...
Name: warpme.vcf
Type: text/x-vcard
Size: 83 bytes
Desc: not available
URL: <http://www.mythtv.org/pipermail/mythtv-users/attachments/20120601/50071eb4/attachment.vcf>