These notes describe problems that lurked in the past or may still be lurking...

I saw a segfault on 2008-01-18, after a TOI cycle with dermixd playing:

[out_alsa.cxx:60] error: [ch0] underrun!
[out_alsa.cxx:60] error: [ch0] underrun!
[in_mpg123.cxx:583] error: [backwatch 0] on reading from mpg123 stderr (16)
Speicherzugriffsfehler

Not reproduced yet, no clue yet.


**************

FIXED: So Bede has some serious looping going on and that reveals issues in the thread concurrency of mpg123_input.
He reloads a short track again and again, which works most of the times, but sometimes gives things like:

[readily_seek 0] decoder working, starting prebuffer reader again
That's a really short track... I have to implement in-buffer seeking
[let_me_die 0] going to commit at 1175323311 because something with 
loading...


[readily_seek 0] decoder working, starting prebuffer reader again
That's a really short track... I have to implement in-buffer seeking
[let_me_die 0] going to commit at 1175323320 because something with 
loading...
That's a really short track... I have to implement in-buffer seeking
[let_me_die 0] going to commit at 1175323325 because something with 
loading...
[readily_seek 0] decoder working, starting prebuffer reader again

even that:

[readily_seek 0] decoder working, starting prebuffer reader again
*** glibc detected *** ./dermixd: free(): invalid pointer: 0x080a1354 ***
underrun!

And, he gets 100% cpu usage that I suspect is still audio_fifo waiting for a non-active thread.
I though I fixed that already, but I have to make the workings more clear.

Hm, got another log:

[readily_clear 0] had read error... going to die


Well, I have one problem with loads failing and the mpg123 input acting suicidal and another one where the fifo reader is not activated where gimme() is waiting feverishly.

**************

FIXED: The new mixplayer nixfade mode, which does the follow command quite short before the leading track ends, triggers a nice picture of silence, here reproduced with a forced seek quite near the end (mixplayer being active on the other line):

dermixd-control> f
in 0:Lena -> (0) stopped at 0s/237.819s (buf: 0) vol: 0.569213 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) playing at 1.95048s/234.24s (buf: 0) vol: 0.606443 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/06-just_to_keep_you_near.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> seek 1 234
success: 233.979
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> f
in 0:Lena -> (0) playing at 0.0464399s/237.819s (buf: 2048) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/07-get_me_a_name.mp3
in 1:Elena -> (0) stopped at 0s/294.165s (buf: 0) vol: 0.637808 speed: 1 eq: 1|1|1, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/08-you_re_on_the_watch.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp
dermixd-control> 


Actually, that's a seek over the end and triggering the follow code after the leader having ended is no good idea...
But still, the result shoud be two channels not playing... when it says playing it should play.
Hm... playing and following...

dermixd-control> f
in 0:Lena -> (0) playing at 11.9351s/206.576s (buf: 0) vol: 0.569213 speed: 1 eq: 1|1|1, following 1:Elena, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/01-killing_me.mp3
in 1:Elena -> (0) stopped at 0.0464399s/283.22s (buf: 2048) vol: 0.637808 speed: 1 eq: 1|1|1, following 0:Lena, 1 actions, dev: mpeg file: /spielwiese/thorma/var/music/lab/2000_porn_beautiful/02-isn_t_he_beautiful.mp3
out 0:Helena <- (0,1) playing dev: oss file: /dev/dsp

That's how it should look. Stopped and follow. Playing and follow dunnae make sense. Here. I mean, following a stopped track...

Resolution: Prebuffered input got activated from outside (mixplayer) without any other active input. Because of the prebuffering the active_inputs counter was not incremented and thus the whole mixing code was skipped.
Endless loop with recognizing a freshly activated prebuffered input followed.
Simple fix is to increment active_inputs in that case, too, and do a sem_post(&insem) at the same place to fake the response from decoder.

**************

VALID? When alsa_threaded is active and subsequently alsa_serial is played... dermixd gets stuck in some loop somewhere... no writer active but full cpu load.
Only seen on the Portege so far. And not seen again, for that matter... So what??

**************

WEIRD: The getstat strings look different on the Alpha box (XP1000 with Sourcemage GNU/Linux) and on the Intel/AMD boxen I have. On Alpha, some of the number strings in getstat are chopped... see mixer_actions.cxx.

**************

FIXED: Too fast OSS playback: Now with the multithreaded double-buffering, OSS playback gets ugly with chunks being written too fast!
Both on native OSS and Alsa OSS emulation. Bummer.
I can restore smooth playback by serializing the playback again (letting the play() return after writer thread having written).
That is no fun: I'm pulling the brake willingly... but I'm lost.
I'm going to re-implement the "normal" serial behaviour for a oss output device and leave the double-buffering one as oss_threaded.

Same went for alsa, but because of different buffering I failed to notice. Solution was to fix a basic mistake in the threaded play(): I swapped buffers and _then_ waited for the sign from writer. Before this sign, the writer is still working with the buffer I'm swapping!

**************

once seen, not reproduced: on the XP1000 with fresh Gentoo GNU/Linux instal, dermixd-1.0.2 or 1.1-trunk:

ls depeche_mode/exciter/*.mp3 | simple_player 

...

dermixd-control stop 0
-> FPE!!!

Wasn't able to reproduce this again:-(

*************

STILL VALID? There are still rare occasions where the thread cancelling on mixer's CLOSE action fails. Why? Is it wise to die on that; we only want the thread to be away and it should be away when getting ESRCH  -- btw, this _is_ included in NPTL since mixer_actions can use it also on the Gentoo machine. I'll have to include another header on output.cpp to get it... if I really want -- or are there zombies stomping?.

*************

FIXED: New output framework (formerly, too?): Output gets silent and dermixd to 100% cpu after some alternated outload oss/alsa; seen it only at changing to OSS...

2 things:
	OSS apparently (according to valgrind) leaks file descriptors. although close(wextra.fd) is calles, they don't get closed!
	This leads to exhaustion eventually and then...
	...dermixd goes raging.
	
	Ah! The open fds came mostly from special_activate being called too often -- the check for active == true was missing in output_device::activate()!
	Still, there are some left. The obvious ones that I don't care about are 0,1,2... but there are 3 and 4:
	
==30889== Open file descriptor 4:
==30889==    at 0x1BBDD04D: pipe (in /lib/libc-2.3.2.so)
==30889==    by 0x1B91D1C7: pthread_create@@GLIBC_2.1 (pthread.c:752)
==30889==    by 0x8063A43: output_device::build(output_data*, unsigned, void* (*)(void*)) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8066542: alsa_output::alsa_output(output_data*, unsigned) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8064160: new_output_device(std::string, output_data&) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8060DD3: outchannel::load(std::string, std::string, comm_data*) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x805E4E9: mixer(bool, int, unsigned short, int) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x80589DC: main (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889== 
==30889== Open file descriptor 3:
==30889==    at 0x1BBDD04D: pipe (in /lib/libc-2.3.2.so)
==30889==    by 0x1B91D1C7: pthread_create@@GLIBC_2.1 (pthread.c:752)
==30889==    by 0x8063A43: output_device::build(output_data*, unsigned, void* (*)(void*)) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8066542: alsa_output::alsa_output(output_data*, unsigned) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8064160: new_output_device(std::string, output_data&) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x8060DD3: outchannel::load(std::string, std::string, comm_data*) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x805E4E9: mixer(bool, int, unsigned short, int) (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)
==30889==    by 0x80589DC: main (in /home/thomas-data/dermp3mixd/dermixd/dermixd_debug)

Pipe... pthread... alsa... do these get worse with multiple loads? No... They were these 2 after several alsa loads... what if alsa channels are added to coexist? No change. Probably this has to be... along with the numerous other complaints of valgrind concerning alsa.

****************

When fixing the follow/gapless stuff, I noticed that the mpg123_input gives me a click (jump in file?) in about the third buffer (1K size) with a 440Hz sine test signal. This happens even without following, but not when playing with mpg123 on the console. There, though, the tone is lower (suspect 220Hz) while in dermixd it has the correct frequency. Also playing a raw file created via

mpg123 -s 440Hz.mp3 > 440Hz.raw_s16

or

mpg123 -s -R --remote-err - > 440Hz.raw_s16
@...
load 440Hz.mp3

plays fine in dermixd (with correct frequency). I'm puzzled here. DerMixD is supposed to have the same sound. Could be something special to such an unreal signal. Don't notice this with music.

***********

Good old Pentium I found another tricky thing: dermixd gets a segmentation fault with quite a probability when
1. static-dermixd-oss runing
2. mixplayer -Ad keeping it busy (-d is important here! With mixplayer printing to the console, it didn't happen... timing...)
3. tplayershell getting "q" 

tplayershell exists, socketeer gets cleaned ... getstat action from mixplayer on the way on another socket... segfault somewhere in there.
Have to check carefully the thread interaction (suspect sth. being destroyed that is still used by other thread; the usage being already history on destruction on faster machines).

Wasn't able yet to reproduce this on another machine with the very same static oss binary (built on knecht with gcc-3.2). Maybe just odd setup?

***********

???: How likely (or possible) is a conflict when both mixer and socketeer write to a socket / handling of socket write errors in general?

***********

FIXED: Memory leaking! Processing of actions non-local to socketeer swallows at least 56 Byte on my laptop (way more on a test Gentoo system with K6-2!). Minimal are getstat/fullstat; others get more.
This is the slow and steady loss... there ist quite a jump in mem usage for new tracks being loaded (decoders created (not destroyed)?)
Before any beta this has to be eliminated!

actions - what happens?

---- socketeer ----
1. socketeer reading msg
2. filling comdat
3. lock, push new action to global list, unlock
4. post actionsem
5. wait for semaphore
---- mixer ----
5. sem_trywait
6. lock, loop over actions
{
	7. create some ints, a string (what for?)
	8. process action (hehe...)
	9. wake socketeer
}
10. actions.clear(), unlock
---- socketeer
11. awake
12. ...

FIXED: I got a logic error: every outload n oss succeedes even if it fails because mixer calls outchannel::load and sets errcode to its return value... intention is that successful outchannel::load() signals successful request to load; actuall error value is supposed to be set by device thread _later_ just before really waking the socketeer. When there is no device tread (as with oss_output - to be changed anyway!), real error code setting and socketeer waking happens during outchannel::load (which doesn't care about real success), with mixer overwriting the value... this could still happen with a device thread and heavy support from the scheduler.


These are old and should be fixed nowadays (save the distortion special to my laptop (?)):

During setup of dermixd + mixplayer as system daemons on my laptop, I stumbled over the situation:

- both started with nice -n -10, but music stopped after some time
- saw that only one mpg123 was (still?) active
- attempted one /rci/mucke stop; where tmixd-control wasn't found
- second attempt with correct PATH resulted in dermixd ragin' on 100% CPU!!!

!!!!!! Seen a segmentation fault !!!!!
during the testing for the cause of distortion (what kind of d. do I mean here?):
- init
- load track on each channel, play 0
- follow 0 1
- vol 1 36
- remin 1
- remin 0 ---> crash

Failed to reproduce this yet. Grrr.
--> check if this can be a mixer error or an mpg123_input destructor error

Maybe resolved by the follower/sampleseek(NULL,...) changes - but when I'm not sure what it was...


Hm. During testing for following/auto-rewind I had a seek to near end that did not end because the seek action got swallowed by a following play action. This _could_ be fixed now with adding !(*ini)->working to the condition for sample ordering/playback... but only when it really wasn't the seek itself, since the status should be different (but buffering?).


Sound distortion: I think this has to do with my laptop's audio driver: OSS output gets distorted after some time and/or workload. But maybe dermixd could do something to prevent this anyway (most probably getting higher priority?)...

