Difference between revisions of "Sound troubleshooting"

From Linuxintro
imported>ThorstenStaerk
imported>ThorstenStaerk
Line 127: Line 127:
 
ok, seems a socket that is open to speaker-test is also open to threaded-ml. So threaded-ml is a thread of speaker-test.
 
ok, seems a socket that is open to speaker-test is also open to threaded-ml. So threaded-ml is a thread of speaker-test.
  
Now which FIFO pipes does the speaker-test process have opened? Let's see:
+
Now process 29145 is currently speaker-test and process 2289 is pulseaudio. strace'ing speaker-test with strace -ffp 29145 I find:
<pre>
+
[pid 29146] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0\0\0\377\377\377\377\0\0\0\20\0\0\0\0@\0\0\0", 20}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 20
linux-fpbq:/proc/29145/fd # lsof | grep threaded- | grep FIFO
+
So speaker-test definitely gets messages from process 2289 and it gets them via file descriptor 7:
threaded- 28370 28400      root    0r    FIFO        0,8      0t0      13908 pipe
+
  linux-fpbq:/proc/29145/fd # ll 7
threaded- 28370 28400      root    6r    FIFO        0,8      0t0    105424 pipe
+
  lrwx------ 1 root root 64 Apr  4 15:44 7 -> socket:[114414]
threaded- 28370 28400      root    7w    FIFO        0,8      0t0    105424 pipe
+
 
threaded- 28370 28400      root  11r    FIFO        0,8      0t0    105597 pipe
+
Now strace'ing pulseaudio with the command strace -ffp 2289 I get:
threaded- 28370 28400      root  12w    FIFO        0,8      0t0    105597 pipe
+
  [pid 2289] send(28, "\0\0\0\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0L\0\0\0=L\377\377\377\377L\0"..., 40, MSG_NOSIGNAL) = 40
threaded- 28370 28400      root  21r    FIFO        0,8      0t0    106549 pipe
+
 
threaded- 28370 28400      root  22w    FIFO        0,8      0t0    106549 pipe
+
In other words, what pulseaudio sends via file descriptor 28 is received by speaker-test via file descriptor 7
threaded- 28370 28400      root  25r    FIFO        0,8      0t0    106552 pipe
 
threaded- 28370 28400      root  26w    FIFO        0,8      0t0    106552 pipe
 
threaded- 28370 28400      root  27r    FIFO        0,8      0t0    105598 pipe
 
threaded- 28370 28400      root  28w    FIFO        0,8      0t0    105598 pipe
 
threaded- 28370 28400      root  30r    FIFO        0,8      0t0    105602 pipe
 
threaded- 28370 28400      root  31w    FIFO        0,8      0t0    105602 pipe
 
threaded- 28370 28400      root  41r    FIFO        0,8      0t0    106557 pipe
 
threaded- 28370 28400      root  42w    FIFO        0,8      0t0    106557 pipe
 
threaded- 28370 28400      root  46r    FIFO        0,8      0t0    106560 pipe
 
threaded- 28370 28400      root  47w    FIFO        0,8      0t0    106560 pipe
 
threaded- 28370 28400      root  51r    FIFO        0,8      0t0    106563 pipe
 
threaded- 28370 28400      root  52w    FIFO        0,8      0t0    106563 pipe
 
threaded- 28370 28400      root  143r    FIFO        0,8      0t0    106858 pipe
 
threaded- 28370 28400      root  144w    FIFO        0,8      0t0    106858 pipe
 
threaded- 28370 28503      root    0r    FIFO        0,8      0t0      13908 pipe
 
threaded- 28370 28503      root    6r    FIFO        0,8      0t0    105424 pipe
 
threaded- 28370 28503      root    7w    FIFO        0,8      0t0    105424 pipe
 
threaded- 28370 28503      root  11r    FIFO        0,8      0t0    105597 pipe
 
threaded- 28370 28503      root  12w    FIFO        0,8      0t0    105597 pipe
 
threaded- 28370 28503      root  21r    FIFO        0,8      0t0    106549 pipe
 
threaded- 28370 28503      root  22w    FIFO        0,8      0t0    106549 pipe
 
threaded- 28370 28503      root  25r    FIFO        0,8      0t0    106552 pipe
 
threaded- 28370 28503      root  26w    FIFO        0,8      0t0    106552 pipe
 
threaded- 28370 28503      root  27r    FIFO        0,8      0t0    105598 pipe
 
threaded- 28370 28503      root  28w    FIFO        0,8      0t0    105598 pipe
 
threaded- 28370 28503      root  30r    FIFO        0,8      0t0    105602 pipe
 
threaded- 28370 28503      root  31w    FIFO        0,8      0t0    105602 pipe
 
threaded- 28370 28503      root  41r    FIFO        0,8      0t0    106557 pipe
 
threaded- 28370 28503      root  42w    FIFO        0,8      0t0    106557 pipe
 
threaded- 28370 28503      root  46r    FIFO        0,8      0t0    106560 pipe
 
threaded- 28370 28503      root  47w    FIFO        0,8      0t0    106560 pipe
 
threaded- 28370 28503      root  51r    FIFO        0,8      0t0    106563 pipe
 
threaded- 28370 28503      root  52w    FIFO        0,8      0t0    106563 pipe
 
threaded- 28370 28503      root 143r    FIFO        0,8      0t0    106858 pipe
 
threaded- 28370 28503      root  144w    FIFO        0,8      0t0    106858 pipe
 
threaded- 29145 29146      root    3r    FIFO        0,8      0t0    114406 pipe
 
threaded- 29145 29146      root    4w    FIFO        0,8      0t0    114406 pipe
 
threaded- 29145 29146      root    5r    FIFO        0,8      0t0    114407 pipe
 
threaded- 29145 29146      root    6w    FIFO        0,8      0t0    114407 pipe
 
linux-fpbq:/proc/29145/fd # ll
 
total 0
 
lrwx------ 1 root root 64 Apr 4 15:44 0 -> /dev/pts/1
 
lrwx------ 1 root root 64 Apr  4 15:44 1 -> /dev/pts/1
 
lrwx------ 1 root root 64 Apr  4 15:44 2 -> /dev/pts/1
 
lr-x------ 1 root root 64 Apr  4 15:44 3 -> pipe:[114406]
 
l-wx------ 1 root root 64 Apr  4 15:44 4 -> pipe:[114406]
 
lr-x------ 1 root root 64 Apr  4 15:44 5 -> pipe:[114407]
 
l-wx------ 1 root root 64 Apr 4 15:44 6 -> pipe:[114407]
 
lrwx------ 1 root root 64 Apr 4 15:44 7 -> socket:[114414]
 
</pre>
 
Note that not every pipe has a file descriptor in the fd folder!
 
  
Now process 29146 is currently speaker-test and process 2289 is pulseaudio. strace'ing speaker-test with strace -ffp 29145 I find:
+
linux-fpbq:/proc/2289/fd # ll 28
[pid 29146] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0\0\0\377\377\377\377\0\0\0\20\0\0\0\0@\0\0\0", 20}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 20
+
lrwx------ 1 root root 64 Apr  4 15:13 28 -> socket:[114415]
So speaker-test definitely gets messages from process 2289.
 

Revision as of 14:38, 4 April 2015

So you want your Linux system to play sound, but it does not? Follow these steps to analyze and solve the problem:

The Methodology

If your cables and volume are okay

  • Test if your sound card driver and cables are okay; play a test sound:
speaker-test

If you hear a sound

If you hear a sound, your cables and drivers are okay.

If you do not hear a sound

If you do not hear a sound, see if you get an error message.

If you do not get an error message

If you do not get an error message, it can be a driver issue. To find out, delete all sound devices and re-create them:

tweedleburg:~ # rm /dev/dsp*
tweedleburg:~ # udevtrigger

Check again with dd if=/dev/urandom of=/dev/dsp. If you still do neither get an error message nor sound, it is most probably a driver issue. Get yourself a USB soundcard and proceed.

If you get an error message

If you get an error message like this:

tweedleburg:~ # dd if=/dev/urandom of=/dev/dsp
dd: opening `/dev/dsp': Device or resource busy

You should find out what process blocks your sound card. Do this with the command lsof (list open files):

tweedleburg:~ # lsof | grep dsp              
mplayer   18251       root    4w      CHR              14,35               14320 /dev/dsp2

You see, mplayer is blocking /dev/dsp2, you third soundcard. Now find out what soundcard you are using:

tweedleburg:~ # ll /dev/dsp*
lrwxrwxrwx 1 root root       9 Jun 21 10:38 /dev/dsp -> /dev/dsp2
crw-rw---- 1 root audio 14, 19 Jun 21 10:36 /dev/dsp1
crw-rw---- 1 root audio 14, 35 Jun 21 10:36 /dev/dsp2

/dev/dsp points to /dev/dsp2, so the soundcard you are using is blocked by mplayer. So, kill mplayer if you are sure that is what you want:

killall mplayer

Knoppix

When there is no sound under Knoppix try

/etc/init.d/alsa-utils start

strace'ing sound

I called

strace -s 99 speaker-test 

verified that I heard sound. I noticed a lot of data was send to the file handle 6:

gettimeofday({1428021206, 3725}, NULL)  = 0
write(1, " 0 - Front Left\n", 16 0 - Front Left
)       = 16
write(6, "W", 1)                        = 1
write(4, "x", 1)                        = 1
futex(0x979b028, FUTEX_UNLOCK_PI_PRIVATE, -1221210112) = 0
gettimeofday({1428021206, 69604}, NULL) = 0
write(6, "W", 1)                        = 1
clock_gettime(CLOCK_MONOTONIC, {175, 791783767}) = 0
write(6, "W", 1)                        = 1
clock_gettime(CLOCK_MONOTONIC, {175, 792229634}) = 0
write(6, "W", 1)                        = 1
clock_gettime(CLOCK_MONOTONIC, {175, 792636529}) = 0
write(6, "W", 1)                        = 1
gettimeofday({1428021206, 71347}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {175, 793286612}) = 0
write(6, "W", 1)                        = 1
clock_gettime(CLOCK_MONOTONIC, {175, 793657888}) = 0
write(6, "W", 1)                      

Then I stopped the process using the CTRL_Z key combination. Then I found speaker-test's PID was 3156. Then I went to the file handles of this process:

linux-fpbq:~ # cd /proc/3156/fd
linux-fpbq:/proc/3156/fd # ll
total 0
lrwx------ 1 root root 64 Apr  2 20:34 0 -> /dev/pts/1
lrwx------ 1 root root 64 Apr  2 20:34 1 -> /dev/pts/1
lrwx------ 1 root root 64 Apr  2 20:33 2 -> /dev/pts/1
lr-x------ 1 root root 64 Apr  2 20:34 3 -> pipe:[19531]
l-wx------ 1 root root 64 Apr  2 20:34 4 -> pipe:[19531]
lr-x------ 1 root root 64 Apr  2 20:34 5 -> pipe:[19532]
l-wx------ 1 root root 64 Apr  2 20:34 6 -> pipe:[19532]
lrwx------ 1 root root 64 Apr  2 20:34 7 -> socket:[19537]

Now speaker-test writes into that file handle. Which process reads from it?

linux-fpbq:/proc/3156/fd # lsof -n +c 15 | grep 19532
speaker-test    3156            root    5r     FIFO        0,8      0t0      19532 pipe
speaker-test    3156            root    6w     FIFO        0,8      0t0      19532 pipe
threaded-ml     3156 3157       root    5r     FIFO        0,8      0t0      19532 pipe
threaded-ml     3156 3157       root    6w     FIFO        0,8      0t0      19532 pipe

seems to be threaded-ml. Threaded-ml is the same process as speaker-test, just another thread. Also, both are subtasks to strace. Also, strace -p'ing speaker-test only yields futex syscalls. This leads nowhere.

However, running speaker-test and strace -p'ing pulseaudio yields a lot of send syscalls to file descriptor 20. Stopping speaker-test removes this file descriptor. While it runs, the file descriptor looks like this:

lrwx------ 1 root root 64 Apr  2 20:32 20 -> socket:[55006]

and - while speaker-test is running the following can be observed:

# lsof | grep 55006
pulseaudi 2842            root   20u     unix 0xf6445040      0t0      55006 /run/user/0/pulse/native
alsa-sink 2842 2847       root   20u     unix 0xf6445040      0t0      55006 /run/user/0/pulse/native
alsa-sour 2842 2848       root   20u     unix 0xf6445040      0t0      55006 /run/user/0/pulse/native

Still this just shows how pulseaudio's threads alsa-source and alsa-sink communicate with each other. The solution is brought by the parameter -ff to strace, finally we find file descriptor 39:

[pid  2847] ppoll([{fd=17, events=POLLIN}, {fd=22, events=POLLIN|POLLERR|POLLNVAL}, {fd=18, events=POLLIN}, {fd=39, events=POLLOUT|POLLERR|POLLNVAL}], 4, {1, 810195000}, NULL, 8 <unfinished ...>

and

[pid  2847] ioctl(39, SNDRV_PCM_IOCTL_HWSYNC, 0xb6bd7570) = 0
[pid  2847] ioctl(28, SNDRV_CTL_IOCTL_ELEM_READ or USBDEVFS_IOCTL, 0xb6208e80) = 0

Note that PID 2847 is a thread of pulseaudio. And that file descriptor 39 is

lrwx------ 1 root root 64 Apr  2 21:53 39 -> /dev/snd/pcmC0D0p

strace'ing sound II

I can hear sound on starting

speaker-test

and I can see with strace that speaker-test triggers activity inside the pulseaudio process. But how do they communicate with each other? First of all let's find out all threads of the speaker-test process:

linux-fpbq:~ # ps -A | grep speaker-test
29145 pts/1    00:00:07 speaker-test
linux-fpbq:~ # cd /proc/29145/fd
linux-fpbq:/proc/29145/fd # ll
total 0
lrwx------ 1 root root 64 Apr  4 15:44 0 -> /dev/pts/1
lrwx------ 1 root root 64 Apr  4 15:44 1 -> /dev/pts/1
lrwx------ 1 root root 64 Apr  4 15:44 2 -> /dev/pts/1
lr-x------ 1 root root 64 Apr  4 15:44 3 -> pipe:[114406]
l-wx------ 1 root root 64 Apr  4 15:44 4 -> pipe:[114406]
lr-x------ 1 root root 64 Apr  4 15:44 5 -> pipe:[114407]
l-wx------ 1 root root 64 Apr  4 15:44 6 -> pipe:[114407]
lrwx------ 1 root root 64 Apr  4 15:44 7 -> socket:[114414]
linux-fpbq:/proc/29145/fd # lsof +c 15 | grep 114414
speaker-test    29145             root    7u     unix 0xf5f19040      0t0     114414 socket
threaded-ml     29145 29146       root    7u     unix 0xf5f19040      0t0     114414 socket

ok, seems a socket that is open to speaker-test is also open to threaded-ml. So threaded-ml is a thread of speaker-test.

Now process 29145 is currently speaker-test and process 2289 is pulseaudio. strace'ing speaker-test with strace -ffp 29145 I find:

[pid 29146] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0\0\0\377\377\377\377\0\0\0\20\0\0\0\0@\0\0\0", 20}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 20

So speaker-test definitely gets messages from process 2289 and it gets them via file descriptor 7:

linux-fpbq:/proc/29145/fd # ll 7
lrwx------ 1 root root 64 Apr  4 15:44 7 -> socket:[114414]

Now strace'ing pulseaudio with the command strace -ffp 2289 I get:

[pid  2289] send(28, "\0\0\0\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0L\0\0\0=L\377\377\377\377L\0"..., 40, MSG_NOSIGNAL) = 40

In other words, what pulseaudio sends via file descriptor 28 is received by speaker-test via file descriptor 7

linux-fpbq:/proc/2289/fd # ll 28
lrwx------ 1 root root 64 Apr  4 15:13 28 -> socket:[114415]