[Defy Android Development] YetAnotherForumUser:
On the missing ringtone bug

Some more info on the missing ringtone bug. Running 20121231 'as is' (other than the usual culled/disabled packages and services).

uptime:

uptime
up time: 1 days, 15:58:21, idle time: 1 days, 00:23:36, sleep time: 14:37:06

On receiving a call, the phone does not produce a ringtone.

Logcat from when the call is placed to when it is dropped on the calling end is attached to this post due to the 30000 char max post limit.

dmesg for the same interval:

cat dmesg-ring
<7>[12695.770263] turning off regulator
<6>[12702.614318] AUDIO_DRIVER:spkr1 = 0x200000, spkr2 = 0x0
<7>[12705.681732] turning off regulator

Interesting observation: while monitoring the interrupt counter (/proc/interrupts) using the watch command (watch -n 1 cat /proc/interrupts (using adb shell)) output from the command is halted while the phone is supposed to be ringing. When the call is dropped on the calling end, output resumes. Redirecting the output from this command to a file also shows this interruption. The most interesting interrupt to watch is number 12 (DMA) since that is used by the sound hardware. It shows the interrupt count on INT 12 to stop increasing at the expected rate (app. 25/second) during the 'blackout'. Here is a sample of the output from the watch command, the call comes in around 16:31:12 and is dropped around 16:31:31. Look at the reported time stamps and notice that most of the output from between the start and drop of the call is missing:

Every 1s: cat /proc/interrupts 2013-01-05 16:31:10

CPU0
11: 8659087 INTC prcm
12: 174094 INTC DMA
21: 898131 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 280387 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53288 INTC sim
37: 4818242 INTC gp timer
56: 742027 INTC i2c_omap
57: 95940 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:11

CPU0
11: 8663141 INTC prcm
12: 174101 INTC DMA
21: 898131 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 280387 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4818296 INTC gp timer
56: 742027 INTC i2c_omap
57: 95940 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:12

CPU0
11: 8663450 INTC prcm
12: 174180 INTC DMA
21: 898548 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 280594 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4818967 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:16

CPU0
11: 8663452 INTC prcm
12: 174225 INTC DMA
21: 901901 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 281949 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4821938 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:31

CPU0
11: 8670745 INTC prcm
12: 174262 INTC DMA
21: 902045 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 282010 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4822067 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:32

CPU0
11: 8673412 INTC prcm
12: 174284 INTC DMA
21: 902045 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 282010 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4822149 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
Every 1s: cat /proc/interrupts 2013-01-05 16:31:33

CPU0
11: 8673520 INTC prcm
12: 174306 INTC DMA
21: 902045 INTC SGX ISR
24: 3823 INTC omap-iommu.0, Omap 3 Camera ISP
25: 282010 INTC OMAP DSS
26: 5 INTC DspBridge	mailbox
28: 0 INTC DspBridge	iommu fault
35: 53322 INTC sim
37: 4822226 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
37: 4822351 INTC gp timer
56: 742534 INTC i2c_omap
57: 95967 INTC i2c_omap
58: 396 INTC omap_hdq
61: 1606 INTC i2c_omap
72: 387 INTC serial idle
73: 0 INTC serial idle
74: 0 INTC serial idle
77: 45321 INTC ehci_hcd:usb1
78: 1269 INTC usbtll
83: 26339 INTC mmc0
86: 196975 INTC mmc1
92: 55683 INTC musb_hdrc
93: 58096 INTC musb_hdrc
94: 2262 INTC TIWLAN_SDIO
160: 14391 GPIO cpcap-irq
170: 0 GPIO bu52014hfv
176: 25590 GPIO isl29030_als_ir
182: 307 GPIO kxtf9_irq
197: 21 GPIO gpio_kp
199: 38 GPIO gpio_kp
225: 79811 GPIO tiwlan0
252: 0 GPIO lm3530_led
259: 40161 GPIO qtouch_ts_int
271: 0 GPIO bu52014hfv
301: 0 GPIO Remote Wakeup
323: 0 GPIO mmc0
337: 0 GPIO gpio_keys
Err: 0

For comparison here is the (filtered) output from the watch command while the same ringtone is playing (by going to Settings->Sound->Phone ringtone and clicking on the current ringtone, it will start playing). The sound starts around 16:53:40. Notice the increase in the INT12 (DMA) counter, app. 25/second.

Every 1s: cat /proc/interrupts 2013-01-05 16:53:38
12: 176974 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:39
12: 176974 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:40
12: 176974 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:41
12: 177000 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:42
12: 177026 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:43
12: 177048 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:44
12: 177071 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:45
12: 177093 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:46
12: 177139 INTC DMA
Every 1s: cat /proc/interrupts 2013-01-05 16:53:48
12: 177169 INTC DMA

If you look back at the first watch command output, you'll notice that the INT 12 count went up by 79 in the first second when the call came in while the normal rate is around 25/second. This could point at a problem in the interrupt handler. It would be interesting to instrument the audio path and watch the output...