Opened 9 years ago

Closed 9 years ago

#8706 closed defect (Invalid)

Position map is not updated during playback of in-progress recordings

Reported by: James Linder <jam@…> Owned by: markk
Priority: blocker Milestone: 0.24
Component: MythTV - General Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

This was reported, had a flurry of fixes, but the bottom line is if you catch up to the 'live point' watching a recording that is recording then mythfrontend exits. Still present in trunk [25437M]

Why M? I've not touched any of this src.

Workaround <pause> then skip until end of commercial (whatever) the <un-pause>

Attachments (7)

mythtv.log (99.9 KB) - added by James Linder <jam@…> 9 years ago.
myth.tgz (48.0 KB) - added by James Linder <jam@…> 9 years ago.
8706_debug.diff (1.1 KB) - added by tralph 9 years ago.
change default readblocksize and add debug for CalcMaxFFTime()
myth.2.tgz (182.7 KB) - added by James Linder <jam@…> 9 years ago.
8706_debug_v2.diff (881 bytes) - added by tralph 9 years ago.
patch to increase the EOF guard band for in-progress recordings
mythnfs.tgz (57.8 KB) - added by James Linder <jam@…> 9 years ago.
mythnonfs.tgz (42.6 KB) - added by James Linder <jam@…> 9 years ago.

Download all attachments as: .zip

Change History (34)

comment:1 Changed 9 years ago by robertm

Owner: set to markk
Status: newassigned

comment:2 Changed 9 years ago by markk

Resolution: Works for me
Status: assignedclosed

I can't replicate this with latest trunk. If it is still a problem, please re-open with a full -v playback log.

Changed 9 years ago by James Linder <jam@…>

Attachment: mythtv.log added

comment:3 Changed 9 years ago by James Linder <jam@…>

Resolution: Works for me
Status: closednew

Nope still present. Here is the full log The movemouse commands are my workaround for gnome-screensaver-command --poke not working. This is a bit of a hack, but works well and does not affect behavior at all. There is lots of guff here, the last page shows exit in response to <right arrow> If anybody wants movemouse.c ask and it shall be posted. James

comment:4 Changed 9 years ago by Kenni Lund [kenni a kelu dot dk]

Status: newassigned

comment:5 Changed 9 years ago by xris

Additional note.. the "live" point that causes exits seems to get stuck if you pull up the cutlist editor. E.g. if you start watching 5 minutes into the show, pull up the cutlist editor briefly (I import the flag list -- not sure if that's related), and then go back to watching, you'll get kicked back to the recording list when you hit the 5 minute point in the recording. If you bring the cutlist editor up again and re-import the flag list, the breakout point moves to the "end" again.

Version 0, edited 9 years ago by xris (next)

comment:6 Changed 9 years ago by xris

Milestone: unknown0.24
Priority: minorblocker

comment:7 Changed 9 years ago by Raymond Wagner

Something that seems related to this are issues with handling interlaced content. The last point in the skip data for these shows gives a bad frame count, as if the content switched from 30fps to 60fps. On all recordings where this happens, it also exhibits the issue where seeking to the end in edit mode will terminate playback.

mysql> select * from recordedmarkup where chanid=4121 and starttime=20100930195900 and (type=4 or type=5) order by mark;
+--------+---------------------+--------+------+------+
| chanid | starttime           | mark   | type | data |
+--------+---------------------+--------+------+------+
|   4121 | 2010-09-30 19:59:00 |      1 |    4 | NULL |
|   4121 | 2010-09-30 19:59:00 |   2676 |    5 | NULL |
|   4121 | 2010-09-30 19:59:00 |  31256 |    4 | NULL |
|   4121 | 2010-09-30 19:59:00 |  35379 |    5 | NULL |
|   4121 | 2010-09-30 19:59:00 |  50120 |    4 | NULL |
|   4121 | 2010-09-30 19:59:00 |  52845 |    5 | NULL |
|   4121 | 2010-09-30 19:59:00 |  57706 |    4 | NULL |
|   4121 | 2010-09-30 19:59:00 | 127973 |    5 | NULL |
+--------+---------------------+--------+------+------+

comment:8 Changed 9 years ago by robertm

Summary: mythfrontend exits when watching a recording at live pointplayback fails when in-progress recording hits end of Position Map

Changing title since the original is completely incorrect (frontend does *not* exit)

comment:9 Changed 9 years ago by sphery

Summary: playback fails when in-progress recording hits end of Position MapPosition map is not updated during playback of in-progress recordings

Changing the title once again to try to further clarify the issue.

In comment:5, xris is saying that he can force a posmap update by entering edit mode.

comment:10 Changed 9 years ago by tralph

James, please update to latest trunk and provide logs with -v playback,file,extra for when the problem occurs.

Changed 9 years ago by James Linder <jam@…>

Attachment: myth.tgz added

comment:11 Changed 9 years ago by James Linder <jam@…>

OK It was hard to get a fail now, so head is much better, but here is the log Watch <down><down>... p[pause] 30 secs p[un pause] <right><right>... Exit to Main Menu

Just <down> and <right> did not abort immediately, hence the fiddle above James

comment:12 Changed 9 years ago by tralph

James, are you recording to a remote storage device like nfs or samba?

comment:13 Changed 9 years ago by tralph

James, the reason the player is exiting is that it is taking too long to access data from your drive. This maybe related to faulty hardware. Could you please run SMART/diags on your disk to see if it has any problems? Also, if it's over a network you might want to make sure the connection doesn't have any issues too.

comment:14 Changed 9 years ago by James Linder <jam@…>

The master (192.168.5.33) records to a local xfs fs. /dev/sda4 on /mnt/store type xfs (rw)

There is a slave at .31 that seldom gets scheduled and it makes no difference if it is up or down.

The viewer is on my machine (192.168.5.31) and behaviour is the same on SuSE 11.2, 11.3, Ubuntu 10.04 and 10.10)

When nfs was enabled for the slave the abort-behaviour was unchanged. The View machine (and the master) are dual core athlon running a 64 bit distro.

Network is an unbusy 100MB. Network monitor A quick test shows network busy (watching) around 10MB including during an abort (no peaks or spikes over about 12MB) I'll check the disk.

comment:15 Changed 9 years ago by James Linder <jam@…>

I'm very naive in this arena, but I see no 'here be dragons`. Anybody able to offer any wisdom?

 sandypit:/var/lib/smartmontools # smartctl -A /dev/sda
smartctl 5.39.1 2010-01-28 r3054 [x86_64-unknown-linux-gnu] (openSUSE RPM)
Copyright (C) 2002-10 by Bruce Allen, http://smartmontools.sourceforge.net

=== START OF READ SMART DATA SECTION ===

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   162   162   021    Pre-fail  Always       -       6866
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       150
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   085   085   000    Old_age   Always       -       11527
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       148
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       15
193 Load_Cycle_Count        0x0032   200   200   000    Old_age   Always       -       150
194 Temperature_Celsius     0x0022   113   102   000    Old_age   Always       -       37
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   100   253   000    Old_age   Offline      -       0

comment:16 Changed 9 years ago by Rob Smith

Status: assignedinfoneeded

Smart data looks clean to me. One thing to check would be to run

iostat -xm 30

Let it run a few minutes before recording (and ignore the very first line), then start recording, let her go for a few minutes, then start playback, let her go a few minutes, and then skip to the end until she quits playback and give her a minute or two.

Also, how full is your XFS partition?

How fragmented is the free space? (xfs_db -c freesp -r /dev/device to check... Might take awhile).

Is your database on the same partition?

comment:17 Changed 9 years ago by James Linder <jam@…>

iostat -xm 30 before and just after abort

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.94    0.21    2.23    0.44    0.00   94.19

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00     2.60    0.00    3.43     0.00     0.02    12.00     0.02    5.31   5.08   1.74

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.57    0.61    6.78    0.90    0.00   89.14

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00   113.33    0.70    9.10     0.01     0.92   193.40     0.09    9.27   7.77   7.61

Free space 

sandypit:/var/lib/smartmontools # xfs_db -c freesp -r /dev/sda4
   from      to extents  blocks    pct
      1       1      30      30   0.00
      2       3      11      29   0.00
      4       7      36     213   0.00
      8      15      22     240   0.00
     16      31     167    2884   0.00
     32      63     225    9137   0.01
     64     127     432   41217   0.03
    128     255    1372  203741   0.15
   1024    2047       2    3518   0.00
   2048    4095       1    2528   0.00
   4096    8191       2    9698   0.01
   8192   16383       2   19620   0.01
  16384   32767       3   73623   0.05
  32768   65535       4  227565   0.17
  65536  131071       6  658840   0.49
 131072  262143       1  143983   0.11
 262144  524287       1  308676   0.23
 524288 1048575       4 2884227   2.13
1048576 2097151       1 1542533   1.14
2097152 4194303       2 6700528   4.95
4194304 8388607       4 26705948  19.71
16777216 33554431       4 95934481  70.81

Finally Disk Useage
sandypit:/var/lib/smartmontools # df /dev/sda4
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/sda4            650517492 109243456 541274036  17% /mnt/store

And finally just of interest: On same hardware this did not happen on 0.23. I've not re-installed 0.23 to retry, but it started as I went to trunk. Somehow my gut feel is that it is not a hardware failure, it may be that trunk is exercising an area of the hardware that 0.23 did not, but I see nothing that looks suspicious.

Database is NOT on same partition

comment:18 Changed 9 years ago by danielk

James, we've come to the same conclusion. The logs tell us that MythTV is requesting data faster than the hard drive can deliver it, which is why we needed to confirm the hard drive is not compromised in some way.

Changed 9 years ago by tralph

Attachment: 8706_debug.diff added

change default readblocksize and add debug for CalcMaxFFTime()

comment:19 Changed 9 years ago by tralph

James, please apply the attached patch and report back with -v playback,file,extra logs. Thanks.

Changed 9 years ago by James Linder <jam@…>

Attachment: myth.2.tgz added

comment:20 Changed 9 years ago by James Linder <jam@…>

I upgraded to latest svn (don't want to know what was) Applied patch

I now cannot provoke an abort despite lots of trying

I attached the trace for interest sake

I was not able to -v playback,file,extra logs: trace complained about liblog... and frontend drew background and went no further. Trace was made with -v playback,file,extra

James

Changed 9 years ago by tralph

Attachment: 8706_debug_v2.diff added

patch to increase the EOF guard band for in-progress recordings

comment:21 Changed 9 years ago by tralph

James, thanks for continuing to help us out. Could you try this newest patch and attach log? I have a theory of what might be happening. Also do you have your recordings directory mounted on your remote machine via nfs or samba? If so, please run another test with the recording directory unmounted on the remote FE to force myth to stream the video and not read via nfs/samba.

comment:22 Changed 9 years ago by tralph

James, also if you are using nfs could you provide your mount options. When using nfs it's required that you turn off attribute caching with actimeo=0. Please see http://www.mythtv.org/wiki/Optimizing_Performance for more information.

comment:23 Changed 9 years ago by James Linder <jam@…>

Ralph fascinating stuff I did not know: If the nfs dir is mounted myth uses it, if it is not mounted then myth streams. All my debug has been of nfs feed (and my problems are associated with nfs mounts [for a slave frontend])
Do you want the patch here in addition to the last patch which "fixes" the problem.
Do you want to see results with nfs feed? (as well as stream)

My concern is that there may not be any problem with stream vs nfs. I need to start again and be clear what does and what does not cause problems

comment:24 Changed 9 years ago by tralph

James, so did you have attribute caching disabled? We'd like you to test the two following scenarios and report back the results.

  1. remount the nfs direcotry with actimeo=0
  1. unmount the /mnt/store directory on your remote frontend

Then please report back with results.

-- Taylor

comment:25 Changed 9 years ago by tralph

James, and please test without the patches applied.

comment:26 Changed 9 years ago by James Linder <jam@…>

No patches, and no aborts despite repeated attempts.

1) sandypit.home:/mnt/store on /mnt/store type nfs (rw,intr,nfsvers=3,bg,actimeo=0,tcp,addr=192.168.5.33)
added nfs stuff as per http://www.mythtv.org/wiki/Optimizing_Performance#Network_File_Systems

2) with no nfs mounts and no aborts.

A storm in a tea cup because I did not understand that NFS would be used if it was available. A lot of effort for folk who have been trying to solve this. Sorry for my naive stupidity.

Again trace attached for interest (I left the VERBOSE trace stuff behind, if there was a problem still it would have been interesting)

Changed 9 years ago by James Linder <jam@…>

Attachment: mythnfs.tgz added

Changed 9 years ago by James Linder <jam@…>

Attachment: mythnonfs.tgz added

comment:27 Changed 9 years ago by tralph

Resolution: Invalid
Status: infoneededclosed

James, no worries and thanks for the quick response. It's a good learning experience for everyone. I'm glad it's working well for you now.

Note: See TracTickets for help on using tickets.