Difference between revisions of "Sound troubleshooting"

From Linuxintro
imported>ThorstenStaerk
imported>ThorstenStaerk
 
(7 intermediate revisions by the same user not shown)
Line 15: Line 15:
 
==== If you do not 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:
 
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*
+
  rm /dev/dsp*
  tweedleburg:~ # udevtrigger
+
  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.
 
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 ====
 
If you get an error message like this:
 
If you get an error message like this:
  tweedleburg:~ # dd if=/dev/urandom of=/dev/dsp
+
  dd if=/dev/urandom of=/dev/dsp
 
  dd: opening `/dev/dsp': Device or resource busy
 
  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):
 
You should find out what process blocks your sound card. Do this with the command lsof (list open files):
  tweedleburg:~ # lsof | grep dsp               
+
<source>
 +
  lsof | grep dsp               
 
  mplayer  18251      root    4w      CHR              14,35              14320 /dev/dsp2
 
  mplayer  18251      root    4w      CHR              14,35              14320 /dev/dsp2
 +
</source>
 
You see, mplayer is blocking /dev/dsp2, you third soundcard. Now find out what soundcard you are using:
 
You see, mplayer is blocking /dev/dsp2, you third soundcard. Now find out what soundcard you are using:
  tweedleburg:~ # ll /dev/dsp*
+
<source>
 +
  ll /dev/dsp*
 
  lrwxrwxrwx 1 root root      9 Jun 21 10:38 /dev/dsp -> /dev/dsp2
 
  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, 19 Jun 21 10:36 /dev/dsp1
 
  crw-rw---- 1 root audio 14, 35 Jun 21 10:36 /dev/dsp2
 
  crw-rw---- 1 root audio 14, 35 Jun 21 10:36 /dev/dsp2
 +
</source>
 
/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:
 
/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
 
  killall mplayer
Line 39: Line 43:
  
 
= strace'ing sound =
 
= strace'ing sound =
I called
+
You know that the [[command]] <tt>speaker-test</tt> does some test noise. To find out if pulseaudio or also is in use, issue:
[[strace]] -s 99 speaker-test  
+
<source>
verified that I heard sound. I noticed a lot of data was send to the file handle 6:
+
strace -s 99 -ff speaker-test
<pre>
+
</source>
gettimeofday({1428021206, 3725}, NULL)  = 0
+
You will find a lot of lines like
write(1, " 0 - Front Left\n", 16 0 - Front Left
+
<source>
)      = 16
+
[pid 15287] write(6, "W", 1)           = 1
write(6, "W", 1)                       = 1
+
[pid 15287] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\2+U\0\0\0\0\0\31vqU\0\0\0\0\0\0\0\0001TU \240\326\0\4\252\354TU \240\326\0\4\262%r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83
write(4, "x", 1)                        = 1
+
[pid 15287] write(6, "W", 1)           = 1
futex(0x979b028, FUTEX_UNLOCK_PI_PRIVATE, -1221210112) = 0
+
</source>
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)                     
 
</pre>
 
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:
 
<pre>
 
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]
 
</pre>
 
Now speaker-test writes into that file handle. Which process reads from it?
 
  
linux-fpbq:/proc/3156/fd # [[lsof]] -n +c 15 | grep 19532
+
'''So what happens here?''' Obviously speaker-test calls the kernel's ''recvmsg'' method. The interesting thing we get from <tt>man 2 recvmsg</tt> is that the first parameter is sockfd, the file descriptor of a socket. So it hands over a socket as a parameter. Let's look at process' file descriptors:
  speaker-test    3156            root   5r    FIFO        0,8      0t0      19532 pipe
+
<source>
  speaker-test    3156            root   6w    FIFO        0,8      0t0      19532 pipe
+
cd /proc/15287/fd
  threaded-ml    3156 3157      root   5r    FIFO        0,8      0t0      19532 pipe
+
ls -l
  threaded-ml    3156 3157      root   6w    FIFO        0,8      0t0      19532 pipe
+
total 0
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.
+
  lrwx------ 1 root root 64 Apr  4 22:55 0 -> /dev/pts/4
 +
lrwx------ 1 root root 64 Apr  4 22:55 1 -> /dev/pts/4
 +
lrwx------ 1 root root 64 Apr  4 22:55 2 -> /dev/pts/4
 +
lr-x------ 1 root root 64 Apr  4 22:55 3 -> pipe:[297487]
 +
  l-wx------ 1 root root 64 Apr  4 22:55 4 -> pipe:[297487]
 +
  lr-x------ 1 root root 64 Apr  4 22:55 5 -> pipe:[297488]
 +
  l-wx------ 1 root root 64 Apr  4 22:55 6 -> pipe:[297488]
 +
lrwx------ 1 root root 64 Apr  4 22:55 7 -> socket:[297495]
 +
</source>
 +
Aha! file descriptor 7 is the unix socket 297495. Let's look what this is connected to:
 +
<source>
 +
ss -p | grep 297495
 +
u_str  ESTAB      0      0      /run/user/0/pulse/native 297496                * 297495  users:(("pulseaudio",2289,28))
 +
u_str  ESTAB      0      0                    * 297495                * 297496  users:(("speaker-test",15286,7))
 +
</source>
  
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:
+
We see - the socket 297495 is connected to the socket 297496. What is written into 297495 will be readable from 297496 and the other way round. This couple of sockets connects the speaker-test process with the pulseaudio process. 2289 is pulseaudio's process id, and 15286 is the root process id of speaker-test. This system is using '''pulseaudio''' for sound which is an important information for troubleshooting sound.
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:
+
= See also =
[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 ...>
+
* [[stRace]]
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:
 
<pre>
 
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
 
</pre>
 
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]
 
 
 
When restarting speaker-test with
 
strace speaker-test
 
I find a line
 
connect(7, {sa_family=AF_LOCAL, sun_path="/run/user/0/pulse/native"}, 110) = 0
 
and then file descriptor 7 plays the same role as before...
 

Latest revision as of 03:55, 1 April 2020

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:

rm /dev/dsp*
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:

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): <source>

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

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

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

</source> /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

You know that the command speaker-test does some test noise. To find out if pulseaudio or also is in use, issue: <source> strace -s 99 -ff speaker-test </source> You will find a lot of lines like <source> [pid 15287] write(6, "W", 1) = 1 [pid 15287] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\2+U\0\0\0\0\0\31vqU\0\0\0\0\0\0\0\0001TU \240\326\0\4\252\354TU \240\326\0\4\262%r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83 [pid 15287] write(6, "W", 1) = 1 </source>

So what happens here? Obviously speaker-test calls the kernel's recvmsg method. The interesting thing we get from man 2 recvmsg is that the first parameter is sockfd, the file descriptor of a socket. So it hands over a socket as a parameter. Let's look at process' file descriptors: <source>

cd /proc/15287/fd
ls -l
total 0
lrwx------ 1 root root 64 Apr  4 22:55 0 -> /dev/pts/4
lrwx------ 1 root root 64 Apr  4 22:55 1 -> /dev/pts/4
lrwx------ 1 root root 64 Apr  4 22:55 2 -> /dev/pts/4
lr-x------ 1 root root 64 Apr  4 22:55 3 -> pipe:[297487]
l-wx------ 1 root root 64 Apr  4 22:55 4 -> pipe:[297487]
lr-x------ 1 root root 64 Apr  4 22:55 5 -> pipe:[297488]
l-wx------ 1 root root 64 Apr  4 22:55 6 -> pipe:[297488] 
lrwx------ 1 root root 64 Apr  4 22:55 7 -> socket:[297495]

</source> Aha! file descriptor 7 is the unix socket 297495. Let's look what this is connected to: <source>

ss -p | grep 297495
u_str  ESTAB      0      0      /run/user/0/pulse/native 297496                * 297495  users:(("pulseaudio",2289,28))
u_str  ESTAB      0      0                    * 297495                * 297496  users:(("speaker-test",15286,7))

</source>

We see - the socket 297495 is connected to the socket 297496. What is written into 297495 will be readable from 297496 and the other way round. This couple of sockets connects the speaker-test process with the pulseaudio process. 2289 is pulseaudio's process id, and 15286 is the root process id of speaker-test. This system is using pulseaudio for sound which is an important information for troubleshooting sound.

See also