avcodec_open/close threading issue

[JohnAStebbins]

I've been seeing a lot of this lately:

Code: Select all

[NULL @ 0x3fe8800]insufficient thread locking around avcodec_open/close()

Handbrake always crashes when this happens.
I narrowed it down to specific instances of avcodec_open that are conflicting and causing that crash. In encavcodec encavcodecInit() and in decavcodec.c decavcodecvWork(). This patch covers those and all other instances of avcodec_open/close.

http://handbrake.fr/pastebin/pastebin.php?show=347

[van]

This has been on my fixit list for a long time & I never got around to it. The patch looks great to me.

[pengc99]

I'm showing the same problem - using Windows GUI v0.9.3

[pengc99]

Also happens with latest svn copy on Linux. One thing of note is both machines I used it on were quad-cpu computers.

[JohnAStebbins]

A fix for this was checked into svn almost a month ago http://trac.handbrake.fr/changeset/2023
I haven't seen this problem since. An honestly, I can't see how it could possibly happen now. There's a lock around every access to avcodec_open/close to prevent it.

[pengc99]

Its happening on both of my computers, one running latest stable and one running SVN as of last night. I would be glad to assist in debugging just tell me what I need to do.

[nightstrm]

Its happening on both of my computers, one running latest stable and one running SVN as of last night. I would be glad to assist in debugging just tell me what I need to do.

Posting a full activity log so we can see what's going on would be a good start.

[JohnAStebbins]

Debugging this isn't exactly easy. To track down the problem last time, I set a brakepoint in ffmpeg where that message is occurring. Do do that, I believe I had to recompile contrib/ffmpeg with debugging enabled. Once I got a break at that location, I had a look at how I got there with a backtrace. That alone is not likely to be enough to get a lead on how this is happening. When you reach that point, it means that some other thread is currently executing in that same function. To figure out what threads are conflicting, I had to add logging before and after every call to avcodec_open/close. But since we've wrapped these functions in locks, there's really only one place to look (which not should be failing like this). You might try verifying that the lock is working properly with something like this.

Code: Select all

Index: libhb/hb.c
===================================================================
--- libhb/hb.c	(revision 2054)
+++ libhb/hb.c	(working copy)
@@ -52,11 +52,17 @@
     av_register_all();
 }
 
+static int avlocked_count = 0;
+
 int hb_avcodec_open(AVCodecContext *avctx, AVCodec *codec)
 {
     int ret;
     hb_lock( hb_avcodec_lock );
+    avlocked_count++;
+    if (avlocked_count > 1)
+        hb_log("This should not happen\n");
     ret = avcodec_open(avctx, codec);
+    avlocked_count--;
     hb_unlock( hb_avcodec_lock );
     return ret;
 }
@@ -65,7 +71,11 @@
 {
     int ret;
     hb_lock( hb_avcodec_lock );
+    avlocked_count++;
+    if (avlocked_count > 1)
+        hb_log("This should not happen\n");
     ret = avcodec_close(avctx);
+    avlocked_count--;
     hb_unlock( hb_avcodec_lock );
     return ret;
 }

If you still get the error, but do not see this new log message, than there is an unwrapped call to avcodec_open/close somewhere. I've looked and I don't see it.

[pengc99]

Oops, looks like I was running the latest stable source 0.9.3, lemme actually try getting the svn version.

Downloading and compiling now...

[moosh]

I'd like to point out that this occurs with the latest stable 0.9.3 on Windows GUI and Linux GUI and Linux CMD. Same errors on all of them.
OS's I've tried include Windows 2003 Server, Windows XP, Ubuntu Linux 8.10, and Red Hat Enterprise Server 4. This happens on both single-CPU and multi-CPU computers, with both hyper-threading and non-hyper-threading computers.

Code: Select all

### Windows GUI 0.9.3 2008112300 
### Running: Microsoft Windows NT 5.1.2600 Service Pack 3 
###
### CPU:               Intel(R) Pentium(R) 4 CPU 3.20GHz 
### Ram: 2047 MB 
### Screen: 1280x1024 
### Temp Dir: C:\Documents and Settings\Andrew Peng\Local Settings\Temp\ 
### Install Dir: C:\Program Files\HandBrake 
### Data Dir: C:\Documents and Settings\Andrew Peng\Application Data\HandBrake\HandBrake\0.9.3.0 
#########################################

### CLI Query:  -i "EDITED" -t 1 -c 1 -o "EDITED" -f m4v -w 320 -e ffmpeg -b 256 -2  -a 1 -E faac -B 80 -R 44.1 -6 stereo -D 1 -v 
#########################################
[23:42:35] hb_init: checking cpu count
[23:42:35] hb_init: starting libhb thread
HandBrake 0.9.3 (2008112300) - http://handbrake.fr/
2 CPUs detected
Opening EDITED...
[23:42:35] hb_scan: path=EDITED, title_index=1
[23:42:35] scan: trying to open with libdvdread
[23:42:35] dvd: not a dvd - trying as a stream/file instead
Input #0, avi, from 'EDITED':
  Duration: 01:46:07.36, start: 0.000000, bitrate: 922 kb/s
    Stream #0.0: Video: mpeg4, yuv420p, 640x272 [PAR 1:1 DAR 40:17], 23.98 tb(r)
    Stream #0.1: Audio: mp3, 48000 Hz, stereo, s16, 80 kb/s
[23:42:37] scan: decoding previews for title 1
[23:42:37] scan: 10 previews, 640x272, 23.976 fps, autocrop = 0/0/0/0, aspect 2.35:1, PAR 1:1
[23:42:37] scan: title (0) job->width:640, job->height:272
Scanning title 1...
[23:42:37] libhb: scan thread found 1 valid title(s)
+ title 1:
  + vts 0, ttn 0, cells 0->0 (0 blocks)
  + duration: 01:46:07
  + size: 640x272, aspect: 2.35, 23.976 fps
  + autocrop: 0/0/0/0
  + chapters:
    + 1: cells 0->0, 0 blocks, duration 01:46:07
  + audio tracks:
    + 1, Unknown (MP3)
  + subtitle tracks:
[23:42:37] 2 job(s) to process
[23:42:37] starting job
[23:42:37] job configuration:
[23:42:37]  * source
[23:42:37]    + EDITED
[23:42:37]    + title 1, chapter(s) 1 to 1
[23:42:37]    + container: avi
[23:42:37]    + data rate: 922 kbps
[23:42:37]  * destination
[23:42:37]    + EDITED
[23:42:37]    + container: MPEG-4 (.mp4 and .m4v)
[23:42:37]  * video track
[23:42:37]    + decoder: mpeg4
[23:42:37]    + frame rate: same as source (around 23.976 fps)
[23:42:37]    + dimensions: 640 * 272 -> 320 * 144, crop 0/0/0/0
[23:42:37]    + encoder: FFmpeg
[23:42:37]      + bitrate: 256 kbps, pass: 1
[23:42:37]  * audio track 0
[23:42:37]    + decoder: Unknown (MP3) (track 1, id 1)
[23:42:37]    + mixdown: Stereo
[23:42:37]    + encoder: faac
[23:42:37]      + bitrate: 80 kbps, samplerate: 44100 Hz
[23:42:37] dvd: not a dvd - trying as a stream/file instead
[23:42:37] sync: expecting 152687 video frames
[23:42:39] reader: first SCR 0
[mp3 @ 0x15a0c80]mdb:12, lastbuf:0 skipping granule 0
[23:42:39] sync: adding 480 ms of silence to audio 0  start 43200, next 0
[00:07:04] reader: done. 1 scr changes
[00:07:05] sync: video time didn't advance - dropped 1 frames (delta 0 ms, current 573054982, next 573058736, dur 3754)
[00:07:05] sync: got 152662 frames, 152687 expected
[00:07:05] work: average encoding speed for job is 104.092819 fps
[00:07:05] mpeg4-decoder done: 152664 frames, 0 decoder errors, 0 drops
[00:07:05] render: lost time: 0 (0 frames)
[00:07:05] render: gained time: 0 (0 frames) (0 not accounted for)
[00:07:05] mp3-decoder done: 0 frames, 0 decoder errors, 0 drops
[00:07:05] starting job
[00:07:05] job configuration:
[00:07:05]  * source
[00:07:05]    + EDITED
[00:07:05]    + title 1, chapter(s) 1 to 1
[00:07:05]    + container: avi
[00:07:05]    + data rate: 922 kbps
[00:07:05]  * destination
[00:07:05]    + EDITED
[00:07:05]    + container: MPEG-4 (.mp4 and .m4v)
[00:07:05]  * video track
[00:07:05]    + decoder: mpeg4
[00:07:05]    + frame rate: same as source (around 23.976 fps)
[00:07:05]    + dimensions: 640 * 272 -> 320 * 144, crop 0/0/0/0
[00:07:05]    + encoder: FFmpeg
[00:07:05]      + bitrate: 256 kbps, pass: 2
[00:07:05]  * audio track 0
[00:07:05]    + decoder: Unknown (MP3) (track 1, id 1)
[00:07:05]    + mixdown: Stereo
[00:07:05]    + encoder: faac
[00:07:05]      + bitrate: 80 kbps, samplerate: 44100 Hz
[00:07:05] dvd: not a dvd - trying as a stream/file instead
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
[NULL @ 0x158bb60]insufficient thread locking around avcodec_open/close()
[00:07:06] reader: first SCR 0
[NULL @ 0x15abc30]insufficient thread locking around avcodec_open/close()
  13898 [unknown (0x12A0)] HandBrakeCLI 416 _cygtls::handle_exceptions: Exception: STATUS_ACCESS_VIOLATION
  15400 [unknown (0x12A0)] HandBrakeCLI 416 open_stackdumpfile: Dumping stack trace to HandBrakeCLI.exe.stackdump

There's the stackdump logfile

Code: Select all

Exception: STATUS_ACCESS_VIOLATION at eip=00498DD9
eax=0004B000 ebx=015ABC30 ecx=00000000 edx=00000000 esi=00000280 edi=1A2DCC94
ebp=00000784 esp=1A2DCAF0 program=C:\Program Files\HandBrake\HandBrakeCLI.exe, pid 416, thread unknown (0x12A0)
cs=001B ds=0023 es=0023 fs=003B gs=0000 ss=0023
Stack trace:
Frame     Function  Args
  19433 [unknown (0x12A0)] HandBrakeCLI 416 _cygtls::handle_exceptions: Exception: STATUS_ACCESS_VIOLATION
  20001 [unknown (0x12A0)] HandBrakeCLI 416 _cygtls::handle_exceptions: Error while dumping state (probably corrupted stack)

[jbrjake]

I'd like to point out that this occurs with the latest stable 0.9.3 on Windows GUI and Linux GUI and Linux CMD.

And you feel this is something that needs to be reported because...?

How could it possibly be fixed in 0.9.3 when the fix didn't get committed until December? How does that make any sense? You didn't even read this thread before you decided to post in it, did you?

[moosh]

Code is added in, I'm recompiling and testing again

[moosh]

Compiled modified code on both Intel and PowerPC under Linux and problem still occurs - nothing different in logs but i'll post the section again anyways, I can't figure out how to pipe the entire verbose output to a logfile so i'm just posting this section:

Code: Select all

[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
[NULL @ 0x9dfe210]insufficient thread locking around avcodec_open/close()
Encoding: task 1 of 2, 99.98 % (119.90 fps, avg 76.80 fps, ETA 00h00m01s)[18:22:37] reader: first SCR 0
[mp3 @ 0x9e01fa0]mdb:12, lastbuf:0 skipping granule 0
[18:22:37] sync: expecting 152687 video frames
[18:22:37] sync: adding 480 ms of silence to audio 0  start 43200, next 0

It doesn't crash like 0.9.3 does (I'm using SVN) but still popping out error messages