[mythtv-commits] Ticket #714: Changes to TFW after 7738 cause IOBOUND to damage files.

[MythTV]

#714: Changes to TFW after 7738 cause IOBOUND to damage files.
--------------------+-------------------------------------------------------
 Reporter:  bjm     |       Owner:  danielk
     Type:  defect  |      Status:  new    
 Priority:  major   |   Milestone:  0.19   
Component:  mythtv  |     Version:  head   
 Severity:  high    |  
--------------------+-------------------------------------------------------
Recently I've had several recordings damaged in a way that prevents files
 from being read past a certain point. In examining the backend logs, the
 following message always appears in the logs at the same point in the
 recording as the point where playback fails.

 2005-11-25 19:30:00.481 TFW, Error: Write() -- IOBOUND begin cnt(11493)
 free(11143)

 ...with only the time, cnt and free values varying. This happens on both
 master an slave and occurs during about 1 in 20 recordings. The logs also
 show the commflagger failing to read the file within two minutes after the
 error. IOBOUND errors have always cropped up every few days but it had
 never resulted in damaged files until jumping from pre-live disable to
 live TV enabled again. The changes to TFW were [7796], [7802], [7816], and
 [7846].

 {{{
 Master log:
 grep '\(IOBOUND\|mpeg4\)' /video/mythtv/mb.log
 2005-10-09 22:56:55.804 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-11 22:31:13.822 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-12 20:58:49.282 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-12 23:43:05.571 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-13 15:59:55.061 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-13 21:29:00.523 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-15 14:13:35.288 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-18 18:02:08.022 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-18 18:59:19.080 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-21 18:35:08.897 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-23 17:13:57.214 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-24 03:15:37.897 IOBOUND - blocking in ThreadedFileWriter::Write()
 [mpeg4 @ 0xb76df924]insufficient thread locking around
 avcodec_open/close()
 2005-10-24 14:49:36.599 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-25 22:45:30.213 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-27 21:16:50.309 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-27 22:38:19.963 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-31 20:24:46.153 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-31 23:37:35.732 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-01 21:05:16.501 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-03 17:40:31.760 IOBOUND - blocking in ThreadedFileWriter::Write()
 [mpeg4 @ 0xb77005a4]insufficient thread locking around
 avcodec_open/close()
 2005-11-04 11:22:14.566 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-04 12:24:26.962 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-11 00:59:57.458 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-11 23:21:06.109 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-16 18:30:04.766 TFW, Error: Write() -- IOBOUND begin cnt(23738)
 free(18330)
 2005-11-16 18:30:04.901 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb76554c4]ac-tex damaged at 28 5
 [mpeg4 @ 0xb76554c4]Error at MB: 183
 [mpeg4 @ 0xb76554c4]concealing 773 DC, 773 AC, 773 MV errors
 2005-11-19 17:06:00.078 TFW, Error: Write() -- IOBOUND begin cnt(19289)
 free(647)
 2005-11-19 17:06:00.867 TFW, Error: Write() -- IOBOUND end
 2005-11-19 17:42:07.947 TFW, Error: Write() -- IOBOUND begin cnt(20545)
 free(3501)
 2005-11-19 17:42:08.535 TFW, Error: Write() -- IOBOUND end
 2005-11-21 18:59:21.348 TFW, Error: Write() -- IOBOUND begin cnt(35215)
 free(9931)
 2005-11-21 18:59:21.598 TFW, Error: Write() -- IOBOUND end
 2005-11-24 09:16:31.369 TFW, Error: Write() -- IOBOUND begin cnt(17257)
 free(8717)
 2005-11-24 09:16:32.344 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb76deee4]1. marker bit missing in 3. esc
 [mpeg4 @ 0xb76deee4]Error at MB: 146
 [mpeg4 @ 0xb76deee4]concealing 807 DC, 807 AC, 807 MV errors
 2005-11-25 11:55:50.924 TFW, Error: Write() -- IOBOUND begin cnt(20143)
 free(20010)
 2005-11-25 11:55:51.315 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb762bee4]slice end not reached but screenspace end (4502 left
 7D04CC, score= -46358)
 [mpeg4 @ 0xb762bee4]concealing 900 DC, 900 AC, 900 MV errors
 }}}

 The 'insufficient thread locking' never resulted in a damaged file. Not
 every show was commflaged to log the mpeg4 errors while reading but I
 believe each file with "TFW, Error: Write() -- IOBOUND" had been
 unreadable past the point of the error, That is, when playing or seeking
 forward, playback treats this point as the end of file and exits to the
 deletion popup.

 {{{
 Slave log:
 grep '\(IOBOUND\|mpeg4\)' /video/mythtv/mb.log
 2005-10-06 20:05:11.537 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-07 08:06:38.127 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-10-07 16:11:18.397 IOBOUND - blocking in ThreadedFileWriter::Write()

 ...about two per day ubtil...

 2005-11-17 21:00:57.362 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-17 21:37:19.809 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-17 23:03:11.831 IOBOUND - blocking in ThreadedFileWriter::Write()
 2005-11-19 17:02:56.153 TFW, Error: Write() -- IOBOUND begin cnt(21726)
 free(15171)
 2005-11-19 17:02:56.556 TFW, Error: Write() -- IOBOUND end
 2005-11-19 19:37:16.062 TFW, Error: Write() -- IOBOUND begin cnt(20687)
 free(7619)
 2005-11-19 19:37:16.921 TFW, Error: Write() -- IOBOUND end
 2005-11-21 03:17:06.558 TFW, Error: Write() -- IOBOUND begin cnt(15610)
 free(11815)
 2005-11-21 03:17:07.879 TFW, Error: Write() -- IOBOUND end
 2005-11-21 20:26:41.210 TFW, Error: Write() -- IOBOUND begin cnt(12579)
 free(4728)
 2005-11-21 20:26:41.436 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb76f3ee4]ac-tex damaged at 12 8
 [mpeg4 @ 0xb76f3ee4]Error at MB: 260
 [mpeg4 @ 0xb76f3ee4]concealing 697 DC, 697 AC, 697 MV errors
 2005-11-22 21:09:21.474 TFW, Error: Write() -- IOBOUND begin cnt(11020)
 free(6820)
 2005-11-22 21:09:22.811 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb763dee4]ac-tex damaged at 17 16
 [mpeg4 @ 0xb763dee4]Error at MB: 433
 [mpeg4 @ 0xb763dee4]concealing 391 DC, 391 AC, 391 MV errors
 [mpeg4 @ 0xb7721ee4]insufficient thread locking around
 avcodec_open/close()
 2005-11-24 20:28:33.093 TFW, Error: Write() -- IOBOUND begin cnt(12718)
 free(2083)
 2005-11-24 20:28:40.713 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb7697ee4]slice end not reached but screenspace end (30886 left
 7D04CC, score= -51406)
 [mpeg4 @ 0xb7697ee4]concealing 900 DC, 900 AC, 900 MV errors
 2005-11-24 21:08:03.086 TFW, Error: Write() -- IOBOUND begin cnt(13486)
 free(11761)
 2005-11-24 21:08:03.420 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb765aee4]concealing 587 DC, 587 AC, 587 MV errors
 2005-11-25 19:30:00.481 TFW, Error: Write() -- IOBOUND begin cnt(11493)
 free(11143)
 2005-11-25 19:30:00.595 TFW, Error: Write() -- IOBOUND end
 [mpeg4 @ 0xb766aee4]header damaged
 [mpeg4 @ 0xb766aee4]header damaged
 }}}

-- 
Ticket URL: <http://svn.mythtv.org/trac/ticket/714>
MythTV <http://www.mythtv.org/>
MythTV