From: <no...@so...> - 2002-03-26 13:26:45
|
Bugs item #527631, was opened at 2002-03-09 00:40 You can respond by visiting: http://sourceforge.net/tracker/?func=detail&atid=101627&aid=527631&group_id=1627 Category: Midlayer Group: normal Status: Open Resolution: Works For Me Priority: 1 Submitted By: Michael Schwendt (mschwendt) >Assigned to: Richard Guenther (richi) Summary: Import WAV broken Initial Comment: I'm running glame 0.6.1 (and 0.6.0) from http://enigma.freshrpms.net on Red Hat Linux 7.2 (Enigma). That binary is compiled with --enable-low-latency. I've found an mp3 which, after converted to WAV with xmms's disk writer, is truncated to random lengths when imported with glame. The mp3 is this one: http://remix64.phatsites.de/?tune=1195 While the source file is 4:11 long, the first time I tried to reproduce this bug and imported the file several times, it ended at 166.441s, the second time at 98.081s, the third time at 203.593s, and so on. These lengths change each time. The exported files are also truncated to those lengths. This is 100% reproducible with this particular file. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-26 11:04 Message: Logged In: YES user_id=62241 This one is worse and made it easy to reproduce. Second import truncated at 43%. launcher: filter track-0 completed. launcher: filter track-1 completed. wait_node: Waiting for track-0. wait_node: Waiting for readfile. printed too early which doesn't look right. launcher: filter readfile completed. waiter: starting cleanup waiter: finished printed at the end. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-26 10:37 Message: Logged In: YES user_id=7575 Sorry to bug you again - but can you update the HEAD CVS version and try again? Thanx, Richard. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-26 00:11 Message: Logged In: YES user_id=62241 Got a "freed 2 buffers created from..." a single time. Probably with one of those rare imports where only track-0 was truncated. Sorry, because this version made it more difficult to reproduce the problem (I need several imports to get the first error, and once it has occurred I need several further imports to get it again), I didn't pay attention until I knew the problem was still there. That progress bar observation explained: it goes normally from left to right in every case as if the complete file is processed. It is NOT that it would stop abnormally somewhere in the middle or so. BUT the following debug output launcher: filter track-1 completed. wait_node: Waiting for track-0. launcher: filter track-0 completed. wait_node: Waiting for readfile. during the import process is printed exactly at that position in the process where the imported track will be truncated. Example: progress bar is in the middle, above debug output is printed, progress bar proceeds normally till the end, launcher: filter readfile completed. waiter: starting cleanup waiter: finished gpsm_vbox_insert: WARNING: doing ordinary remove on vbox_insert is printed, imported file turns out to be truncated near the middle. You can substitute "middle" with an arbitrary position. If the progress bar is near 80% and those debug output lines are printed then, files ends truncated around 80% despite the file being process till the end and the progress bar moving towards the end, too. (Normally, that debug output is printed when the import procedure is really done, with the progress bar at the end.) Hope this is explained better. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 23:37 Message: Logged In: YES user_id=7575 But it didnt drop buffers appearently. Also the progressbar cant move further after both track-0 and track-1 completed - did it? Was the file truncated to about half the right size? I cannot think how this can be a pthreads bug, as pthread is only involved at initialization and cleanup time. In other words, its weird. Richard. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 21:48 Message: Logged In: YES user_id=62241 Mixed results with the HEAD branch. In the beginning, made it quite more difficult to reproduce the problem. For the first eight (!) imports, I only got two times a truncated track-0. track-1 was always okay. However, then I got both tracks truncated. One new observation with this version: when the import is bad, it printed "launcher: filter track-%d completed." debug messages _before_ the progress bar has reached the end, like this: filter_launch: all nodes launched. filter_start: waiting for nodes to complete initialization. swapfile_out_f: track-1 is ready now. read_file_f: readfile is ready now. swapfile_out_f: track-0 is ready now. [Ed: starts importing here.] launcher: filter track-1 completed. wait_node: Waiting for track-0. launcher: filter track-0 completed. wait_node: Waiting for readfile. [Ed: above lines put out around 50%.] launcher: filter readfile completed. waiter: starting cleanup waiter: finished [Ed: above lines put out at end of import.] E.g. when the truncated tracks are 80% the original size, it printed this around 80% of the progress bar. Too early, in other words. Not the case with good imports. ----- With Red Hat Linux beta with the same $HOME partition, I have been unable to reproduce this problem. And I've tried many times. Makes me believe something in glibc/pthreads might be fixed there. Of course, it could also be different timing, newer kernel, etc. But how likely is that?! ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 20:36 Message: Logged In: YES user_id=7575 Well thinking about this bug, it cant really be a cleanup race condition - but somehow it has to be... So, if you have the time - can you try the HEAD branch of the CVS to which I committed a different "fix" just a minute ago? ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 17:12 Message: Logged In: YES user_id=62241 Well, I suspect, if it didn't hang, the imported file would end up truncated. ;-) ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 17:09 Message: Logged In: YES user_id=62241 Rebuilt with updated CVS tree. Hangs are not gone unfortunately. I import the file mentioned in the first comment two times. The 2nd time it hangs "wait_node: Waiting for readfile." forever. CTRL+C works. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 16:51 Message: Logged In: YES user_id=7575 Ok, can you update the cvs again (I committed two additional fixes) and try that together with patch #2 (that didnt show bad imports, but just hanged)? The hangs should be gone (crossing fingers) - if it still imports ok I think I know whats going wrong (but still dont believe it...). Thanx, Richard. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 16:47 Message: Logged In: YES user_id=62241 Same problem with CVS version: launcher: filter track-1 completed. wait_node: Waiting for track-0. launcher: filter track-0 completed. wait_node: Waiting for readfile. launcher: filter readfile completed. waiter: starting cleanup postprocess_node: freed 4 buffers created by readfile waiter: finished gpsm_vbox_insert: WARNING: doing ordinary remove on vbox_insert drag_start_stop_cb: illegal modifier ---------------------------------------------------------------------- Comment By: Daniel Kobras (nold) Date: 2002-03-25 16:30 Message: Logged In: YES user_id=7832 This version.texi thing is an automake screwup. "make -C doc stamp-vti; touch doc/stamp-vti.1" fixes it. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 16:26 Message: Logged In: YES user_id=62241 With the 2nd patch applied, everything imports fine. I had tested a dozen imports until I a deadlock killed the current session. I "waits forever for readfile" at arbitrary file positions when importing a second (or >= 2nd) file, with this being the last lines of the debug output: filter_launch: initting nodes filter_launch: launching nodes launch_node: issuing pthread_create for node track-1 launcher: track-1 launched (pid 15232) filter_after_init_hook: track-1 seems ready for signalling launch_node: issuing pthread_create for node track-0 launcher: track-0 launched (pid 15233) filter_after_init_hook: track-0 seems ready for signalling launch_node: issuing pthread_create for node readfile launcher: readfile launched (pid 15234) filter_after_init_hook: readfile seems ready for signalling filter_launch: waiting for nodes to complete initialization filter_launch: launching waiter wait_node: Waiting for track-1. filter_launch: all nodes launched. filter_start: waiting for nodes to complete initialization. swapfile_out_f: track-1 is ready now. swapfile_out_f: track-0 is ready now. af_read_f: readfile is ready now. launcher: filter track-1 completed. wait_node: Waiting for track-0. launcher: filter track-0 completed. wait_node: Waiting for readfile. Could this be the same arbitary file positions where the unpatched version truncates imported files? CVS v0_6 has problems in the doc dir, missing version.texi. Will need to look into it. Probably give it a try as a separate build rather than RPM'ified. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 15:50 Message: Logged In: YES user_id=7575 The only other thing I can imagine to have a race (I'm convinced it has not, but probably I'm blind on this issue, as I coded that) is the cleanup code. Can you apply the second attached patch and look, if it changes anything? At least that would give us some hint. Richard. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 15:47 Message: Logged In: YES user_id=7575 Yes, the problem is the fbuf_free_buffers - its just dropping two chunks of data in some cases, but I cant see how this can happen. The fbuf_free_buffers is after everything is single-threaded again - before there are no paths in the code where it can possibly leave buffers hanging around, so I'm very confused at the moment. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 15:43 Message: Logged In: YES user_id=62241 No, not a high-end system. It's an AMD Duron 650 MHz, 256 MiB SDRAM, Gigabyte 7ZX mainboard, Seagate ST320423A hard-drive. Fully updated Red Hat Linux 7.2, kernel 2.4.9-31, glibc 2.2.4-19.3. Runs stable for a very long time. No similar problems with other software. Looking for threading-related problems seems to be the right direction. Do you have any comment on my observation with regard to fbuf_free_buffers? ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 15:38 Message: Logged In: YES user_id=7575 Also, can you try out the current stable (v0_6 branch) CVS? It has a cleanup'ed file import from the unstable branch - it shouldnt fix anything, but who knows (at least it adds error handling). Thanx again, Richard. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 15:26 Message: Logged In: YES user_id=7575 To help us reproduce the bug, can you tell us something about your machine? I.e. is it rather fast (new Athlon/P4) or very slow (old Pentium, etc.)? Anything unusual (not ix86 architecture)? Very strange bug... Richard. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 15:16 Message: Logged In: YES user_id=62241 Didn't fix it. Again, the first bad import had this extra line in debug output: waiter: starting cleanup -> fbuf_free_buffers: freed 4 buffers waiter: finished All others were good and didn't have that line. Also, the activity in the progress bar pretends the complete file was imported. Nevertheless, the final result is truncated (both according to number of samples and length in seconds). Btw, I'll later try it again on Red Hat Linux beta version, mounting a partition on the same hard-drive. I bet timing is an issue here. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-25 14:43 Message: Logged In: YES user_id=7575 Can you try to apply the attached patch? It fixes a possible race on import. Thanx, Richard. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 11:41 Message: Logged In: YES user_id=62241 A second typescript attached. Same symptoms. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-25 11:40 Message: Logged In: YES user_id=62241 Good tip. I can reproduce the problem also with the internal audiofile replacement. Complete typescript is attached. I've rebuilt glame 0.6.1 with the libaudiofile code in "configure" taken out. config.h ends with undefined HAVE_AUDIOFILE. libaudiofile is linked only for ESD/GNOME, I think. Additionally, I've set --enable-debug and --enable-swapfiledebug. Debug output is a bit confusing. Seems libaudiofile is still used for taking a first peek at a WAV header. But "afOpenFile: Using internal audiofile replacement." suggests, it is not used for the actual reading. The typescript includes a few _good_ import/delete operations and ends with a last truncated import operation. An 8:11 minutes long file ends at 227.370s. "df" proves that enough space is left in $HOME. A bad import has waiter: starting cleanup -> fbuf_free_buffers: freed 4 buffers waiter: finished in the debug log while a good import has just: waiter: starting cleanup waiter: finished Any further ideas? pthreads an issue? ---------------------------------------------------------------------- Comment By: Daniel Kobras (nold) Date: 2002-03-25 00:38 Message: Logged In: YES user_id=7832 It's really hard to tell what causes this bug for we can't reproduce this behaviour so far. Since bleeding-edge RH works okay, apparently, this really sounds like some weirdness in a lib, rather than in glame itself. You're absolutely positive that glame on RH 7.2 used the uptodate audiofile, rather than some ancient version still lurking on the drive? Furthermore, you can try to comment out the '#define HAVE_AUDIOFILE 1' in config.h just after running configure, and re-compile glame (make clean, make), so it will use a basic internal wav loader instead of audiofile's. In short, I don't have the faintest idea what might be going on. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-24 17:51 Message: Logged In: YES user_id=62241 Upgrading libaudiofile to 0.2.3 _and_ rebuilding glame 0.6.1 didn't help on Red Hat Linux 7.2 (same stable machine, just a different hard-drive). While I'm typing this I have two other WAV files with which the problem is top reproducible, even when I start from scratch (rm -rf ~/.glamerc ~/.glameswap). I import the first one. Okay. I import the second one. It ends truncated, 20s missing. Lots of free space available. I import the second one another time without deleting the previous track. It ends with an even different truncated size (216.967s instead of 8:22 minutes). I import it again as the fourth track, it imports completely. Absolutely weird. Something is terribly wrong here with glame 0.6.1 on Red Hat Linux 7.2. I'll keep an eye on this... ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-24 16:51 Message: Logged In: YES user_id=62241 Two corrections: - it is NOT 100% reproducible unfortunately - it can happen with other WAV files, too I was happy to find that WAV file mentioned in the first comment, because I could import it arbitrary times, and it would always end up with a different length. It was my assumption that internal calculations on this specific WAV file would be the cause of these import errors. Other WAV files worked fine at the same time. However, I just found that it needs more than just importing this file one or multiple times. On Red Hat Linux 7.2 (fully updated) I just had to import, delete, empty deleted, a couple of files until the error occured for track 0 of 1 of a newly imported file. That track ended up shorter than the second. Lack of glame swap space is surely not a problem on that machine. /home, where glameswap is located, has plenty of space. Right now on Red Hat Linux 7.2.92 (beta), with libaudiofile 0.2.3 I seem unable to reproduce this bug so far. I've gone through a loop of importing, deleting, etc. several WAVs a dozen times, but without errors. :) I'll probably go and see how Red Hat 7.2 behaves when it try to update libaudiofile 0.2.1 there. ---------------------------------------------------------------------- Comment By: Michael Schwendt (mschwendt) Date: 2002-03-24 15:11 Message: Logged In: YES user_id=62241 Hmmm, so you think it is a bug in libaudiofile? $ rpm -q audiofile audiofile-0.2.1-2 Because creating/saving the WAV with XMMS is fine. I'll try it later on Red Hat's current beta version. ---------------------------------------------------------------------- Comment By: Richard Guenther (richi) Date: 2002-03-24 14:34 Message: Logged In: YES user_id=7575 Seems to be libaudiofile version (for the loading part) or xmms version (for the saving part) related. At least I'm not able to reproduce this behavior. ---------------------------------------------------------------------- You can respond by visiting: http://sourceforge.net/tracker/?func=detail&atid=101627&aid=527631&group_id=1627 |