Mailing List Archive: MythTV: Users

recent "TFW -- took a long time" warnings

Index | Next | Previous | View Threaded

warpme at o2

May 31, 2012, 12:50 PM

Post #1 of 6 (457 views)
Permalink

recent "TFW -- took a long time" warnings

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

Attachments:

warpme.vcf (83 B)

warpme at o2

Jun 1, 2012, 8:15 AM

Post #2 of 6 (439 views)
Permalink

Re: recent "TFW -- took a long time" warnings [In reply to]

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
> 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 + 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

Attachments:

warpme.vcf (83 B)

warpme at o2

Jun 1, 2012, 8:16 AM

Post #3 of 6 (439 views)
Permalink

Re: recent "TFW -- took a long time" warnings [In reply to]

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
> 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

Attachments:

warpme.vcf (83 B)

warpme at o2

Jun 22, 2012, 2:26 PM

Post #4 of 6 (372 views)
Permalink

Re: recent "TFW -- took a long time" warnings [In reply to]

Attachments:

warpme.vcf (83 B)

danielk at cuymedia

Jun 22, 2012, 7:01 PM

Post #5 of 6 (364 views)
Permalink

Re: recent "TFW -- took a long time" warnings [In reply to]

On 06/22/2012 05:26 PM, Warpme wrote:
> If anybody experiencing issue like described in my original post:
> it is worth to check kernel VM settings regarding dirty pages swapping.
> Pls do test with following:

I haven't been seeing the TFW errors, but that the virtual memory
settings have anything to do with it is interesting. How much
virtual memory is your mythbackend process consuming?

-- Daniel
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://www.mythtv.org/mailman/listinfo/mythtv-users

warpme at o2

Jun 24, 2012, 1:14 AM

Post #6 of 6 (357 views)
Permalink

Re: recent "TFW -- took a long time" warnings [In reply to]

On 6/23/12 4:01 AM, danielk wrote:
> On 06/22/2012 05:26 PM, Warpme wrote:
>> If anybody experiencing issue like described in my original post:
>> it is worth to check kernel VM settings regarding dirty pages swapping.
>> Pls do test with following:
>
> I haven't been seeing the TFW errors, but that the virtual memory
> settings have anything to do with it is interesting. How much
> virtual memory is your mythbackend process consuming?
>
> -- Daniel
> _______________________________________________
> mythtv-users mailing list
> mythtv-users [at] mythtv
> http://www.mythtv.org/mailman/listinfo/mythtv-users
>
Hi Daniel,

Currently it is 1,67G while RSS is 122M.
I have 4G RAM, no swap. BE is only console (no GFX shell) so normally I
have 2,4-2,7G allocated as buffers.

Some comments form my side :-)
Distribution of TFW errors (they are consolidated around short periods
of time) and lack of any correlation with other user process activity
directed me to dirty pages/swap area.
I was skeptic about swap as having no swap there shouldn't be aspects
related to swapiness, but dirty pages write-out were good candidate to
investigate.
According to various sources, when pdflush daemons are writing huge
amounts of dirty pages (on systems with high dirty_ratio), they
potentially can produce "write-hog" and periodically block all I/O on
the system.
Fortunately fine tuning (exact amount, not % in installed RAM) was
addressed in https://lkml.org/lkml/2008/11/23/160
I decided to implement strategy: lets VM dirty_pages writes-out will be
with possible minimal amount of dirty pages as write-out is quite
expensive from real-time point of view. Price of this strategy are
frequent writes, but it is much less than default behavior where in
worst case kernel potentially can write-out 40% in single period of time
(=1,6G my case as kernel default dirty_ratio is 40%). So I set
vm.dirty_background_bytes = 102400.

My lessons learn are following:
-If there are TFW errors, first thing worth to check is their
correlations with other user space activities (like copying huge files,
etc).
-If there is no visible correlation then it is worth to look on their
distribution. If distribution is regular - probably system has issue
with IO BW or IO subsystem has problems itself (failing drive, etc).
-If they are consolidated, then probably issue is like mine: kernel
dirty_pages write-outs strategy. It is worth to launch:
watch -n1 grep -A 1 dirty /proc/vmstat
and look on nr_dirty variations.

-br

Attachments:

warpme.vcf (83 B)

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads