[mythtv-users] Truncated-deletes patch no longer truncates

[Yeechang Lee]

As I've previously written
(<URL:http://www.gossamer-threads.com/lists/mythtv/users/218771#218771>
and, earlier,
<URL:http://www.gossamer-threads.com/lists/mythtv/users/208741#208741>
and
<URL:http://www.gossamer-threads.com/lists/mythtv/users/208763#208763>),
I use Boleslaw's patch (<URL:http://svn.mythtv.org/trac/ticket/1835>;
specifically, gradual-delete3.patch) for truncated deletions so as to
not lock my ext3-based NAS (and thus cause IOBOUND and 'TFW:
safe_write(): funky usleep' errors) when deleting files of more than a
couple of gigabytes in size. It's worked quite well on my ATrpms
0.19-fixed system for more than two months.

Suddenly, the patch has stopped working properly. Through Friday
night, the patch would work like so:

    2006-08-25 21:22:53.928 About to unlink/delete file:
    '/misc/cube/mythtv/store/Walt_Disney_World_Ultimate_10_-_2006-08-23,_11-00_AM,_ch1170.mpg'
    2006-08-25 21:23:01.228 AutoExpire: File truncates are pending
    2006-08-25 21:23:01.229 Reschedule requested for id 0.
    2006-08-25 21:23:01.229 Truncating
    '/misc/cube/mythtv/store/Walt_Disney_World_Ultimate_10_-_2006-08-23,_11-00_AM,_ch1170.mpg'
    by 124.88 MB every 10 seconds

    [...]

    2006-08-25 21:27:35.129 AutoExpire: Waiting for pending file truncates
    2006-08-25 21:33:13.816 Finished truncating
    '/misc/cube/mythtv/store/Walt_Disney_World_Ultimate_10_-_2006-08-23,_11-00_AM,_ch1170.mpg'

This was a one-hour HD recording of about 7.5GB, so you can see that
taking ten minutes to completely truncate it is about right.

The above was the last successful truncated delete. The following fact
may or may not be relevant: A little bit later, I shut down
mythbackend in order to update the firmware on my NAS, an Infrant
ReadyNAS 600, to the newest version, then started mythbackend
again. (I mount the recordings directory using CIFS, for reasons I
outline in
<URL:http://www.gossamer-threads.com/lists/mythtv/users/169825#169825>.
Testing I conducted while dealing with the below problem indicated
that creating a 1GB empty file take 284s with SMBFS+lfs, 164s with
NFS, and 118s with CIFS.)

Starting this morning, I see instead:

    2006-08-26 10:29:01.218 About to unlink/delete file:
    '/misc/cube/mythtv/store/Late_Show_With_David_Letterman_-_2006-08-25,_11-34_PM,_ch1161.mpg'
    2006-08-26 10:29:08.763 Reschedule requested for id 0.
    2006-08-26 10:29:08.784 AutoExpire: File truncates are pending
    2006-08-26 10:29:08.785 Truncating
    '/misc/cube/mythtv/store/Late_Show_With_David_Letterman_-_2006-08-25,_11-34_PM,_ch1161.mpg'
    by 124.88 MB every 10 seconds
    2006-08-26 10:29:08.787 Finished truncating
'/misc/cube/mythtv/store/Late_Show_With_David_Letterman_-_2006-08-25,_11-34_PM,_ch1161.mpg'

Note the timestamps of the last two 'truncating' messages; needless to
say, the system has obviously not completely truncated a 7.5GB
recording in 0.002 seconds!

I've tried the usual fixes, with no change in behavior:

* Restart mythbackend.
* Recompile MythTV after applying the truncate patch (but now using
  the 130 ATrpms SRPM; I had used 129 before).
* Try out a newer version of the truncate patch. Unfortunately,
  1835-v5.patch, which I presume is the one now in SVN and ready for
  0.20, won't patch cleanly on 0.19-fixes.
* Make sure the recordings I'm deleting have the proper filesizes in
  the database.
* Speaking of which, before Michael Dean asks, yes, I've run
  optimize_mythdb.pl manually; I already have it set to run every
  night in crontab.

The one thing I suspect but can't test is that the NAS firmware
upgrade changed the cifs mount's behavior in some way that causes the
Boleslaw patch to think that the file is immediately
truncated. Everything else, as far as I can tell, still works fine,
including playbacks, recordings, and transcodes.

Suggestions?

-- 
Yeechang Lee <ylee at pobox.com> | +1 650 776 7763 | San Francisco CA US