Kaffeine hangs with 99% CPU after half hour of DVB recording

Bug #24287 reported by Richard Theil on 2005-10-19
6
Affects Status Importance Assigned to Milestone
kaffeine (Ubuntu)
Medium
Jonathan Riddell

Bug Description

Platform: Ubuntu 5.10, stock install, universe/multiverse
enabled plus Kaffeine (also saw 17109/18072 btw.) and
appropriate codecs.

Hardware: AMD AthlonXP 1700 ("Palomino") on Epox EP-8KHA+
Avermedia 771 DVB-T Card (DVB-BT878 and MT352 Tuner)

Version: kaffeine (& -xine & -gstreamer) 0.7-0ubuntu4
kaffeine set to kaffeine-xine backend (to work around the
flaws with gstreamer like jerky motion and ghosted channels
for DVB in kaffeine (two bugs on their own...))

Severity: Grave. This bug renders non-reproducible
data useless when recordings of one-time broadcasts
get cut off.

Description: A DVB channel is set in kaffeine, immediate
recording is activated for it, then it is displayed in
the player tab. After roughly half an hour, the picture
freezes, the recording stops and the CPU use for kaffeine
goes to 99%. The rest of the system still responds fine.

Reproducibility: Haven't tried yet, lacking the time.
I considered this failure annoying enough though, to
warrant immediate filing, even if this happens only as
a 5% fluke. I also don't have permanent access to the
machine (it lives 'round my parents).

Further details: Recording has been done in the
Rhein-Main area of Germany from VHF Bocquet 1 at
198.5 MHz (Das Erste) over a room aerial that had
limited signal quality on that frequency (very rare
errors on blocks in the picture were observed), so
a codec issue with the live view might not be ruled
out.

Logs: Anticipating trouble, I ran kaffeine in a
terminal, excerpt below, annotated. Unfortunately I
didn't try to attach gdb or strace to the hung task.

### excerpt starts, instant recording clicked
Recording started : Das Erste
NOUT : 1
Audiostream: Layer: 2 BRate: 192 kb/s Freq: 48.0 kHz
### Frame size from a news programme. Looks perfectly fine so far.
Videostream: ASPECT: 4:3 Size = 704x576 FRate: 25 fps BRate: 7.00 Mbit/s
Launched ok, pid = 8432
OggS-SEEK: at 0 want 60408 got 51136 (diff-requested 60408)
OggS-SEEK: at 60352 want 520 got 0 (diff-requested -59832)
X Error: BadWindow (invalid Window parameter) 3
  Major opcode: 20
  Minor opcode: 0
  Resource id: 0x30008c4
X Error: BadWindow (invalid Window parameter) 3
  Major opcode: 20
  Minor opcode: 0
  Resource id: 0x30008c4
X Error: BadWindow (invalid Window parameter) 3
  Major opcode: 18
  Minor opcode: 0
  Resource id: 0x30008c4
kaffeine: Kaffeine: Fake keypress event
kaffeine: KXineWidget: New video frame size: 1014x576 - aspect ratio: 1.45455
### Here the normal-screened news program ended and the widescreen movie begun.
kaffeine: KaffeinePart: got new frame size from xine
kaffeine: Kaffeine: new video frame size: 1014x576
kaffeine: Kaffeine: autoresize: old size: 765x725, video size: 1014x576, player
size: 761x576, resize to: 10 18x725
kaffeine: Kaffeine: autoresize: old size: 1018x725, video size: 1014x576, player
size: 1014x576, resize to: 1018x725
kaffeine: Kaffeine: Fake keypress event
### kaffeine issues keypresses to avoid the screensaver coming on
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
kaffeine: Kaffeine: Fake keypress event
### I don't know if it went wrong precisely here?!
kaffeine: Kaffeine: Mouse press event
### Why would arts run if normal ubuntu runs esd?
### (the xine engine is set to "auto" detect by stock install)
warning: leaving MCOP Dispatcher and still 14 object references alive.
  - Arts::SampleStorage
  - Arts::Synth_MULTI_ADD
  - Arts::Synth_MULTI_ADD
  - Arts::Synth_PLAY
  - Arts::StereoVolumeControl
  - Arts::StereoEffectStack
  - Arts::Synth_BUS_DOWNLINK
  - Arts::SoundServerV2
  - Arts::Synth_BUS_UPLINK
  - Arts::AudioManagerClient
  - Arts::Synth_AMAN_PLAY
  - Arts::Synth_BUS_UPLINK
  - Arts::AudioManagerClient
  - Arts::Synth_AMAN_PLAY
warning: leaving MCOP Dispatcher and still 151 types alive.
kaffeine: Kaffeine: Mouse press event
kaffeine: Kaffeine: Mouse press event
kaffeine: Kaffeine: Fake keypress event
Launched ok, pid = 10305
OggS-SEEK: at 0 want 60408 got 51136 (diff-requested 60408)
OggS-SEEK: at 60352 want 520 got 0 (diff-requested -59832)
### unfortunately I didn't take note what of this happened before
### or after the failure :(
Asked to stop
pipe closed
Live stopped
kaffeine: Kaffeine: destructor
kaffeine: KXineWidget: xine event: playback finished
ICE default IO error handler doing an exit(), pid = 8429, errno = 0

Richard Theil (richard-theil) wrote :
Download full text (4.4 KiB)

Sorry for the stuff without reproduction details, writing
software for a living I know how annoying these low-frequency
glitches are to track down, so I browsed the logs a bit more
for further forensic hints:

Exhibit 1: It does not seem to be a memory leak

top - 20:16:30 up 20 min, 3 users, load average: 1.31, 1.61, 1.12
Cpu(s): 40.3% us, 2.3% sy, 0.0% ni, 56.3% id, 0.0% wa, 0.3% hi, 0.7% si
Mem: 256796k total, 233132k used, 23664k free, 5176k buffers
 7548 annelies 15 0 166m 41m 25m S 26.3 16.7 3:59.34 kaffeine

top - 21:44:47 up 1:48, 3 users, load average: 1.26, 1.12, 1.22
Cpu(s): 99.0% us, 0.3% sy, 0.0% ni, 0.0% id, 0.0% wa, 0.3% hi, 0.3% si
Mem: 256796k total, 250284k used, 6512k free, 4200k buffers
 7548 annelies 15 0 166m 42m 25m S 97.1 16.9 52:38.15 kaffeine

Exhibit 2: The file was modified half an hour after the usable stream ends,
but half an hour before I interrupted the hanging process.

ls -l done at different times, note how the file grows at the beginning but
ceases to grow
later. The first two entries were done in "real time" (date stamp current), but
the last
two entries were done at 21:44, according to top, so the last write was half an
hour ago.
When played back in Xine, the playback ends at 00:29:05.

-rw-r--r-- 1 anneliese anneliese 10190848 2005-10-19 20:17 Das
Erste-05.10.19-20:16:53.mpg
-rw-r--r-- 1 anneliese anneliese 26664960 2005-10-19 20:17 Das
Erste-05.10.19-20:16:53.mpg
-rw-r--r-- 1 anneliese anneliese 1567719424 2005-10-19 21:14 Das
Erste-05.10.19-20:16:53.mpg
-rw-r--r-- 1 anneliese anneliese 1567719424 2005-10-19 21:14 Das
Erste-05.10.19-20:16:53.mpg

Exhibit 3: Nothing obvious in the syslog (syslogd has a rather high pid?!),
but what's knotify doing in there? Trying to use arts? Causing trouble?
(I did not even enter the room with the machine between 20:20 and 21:40)

 7548 pts/1 Sl 52:13 kaffeine
 7552 ? Ss 0:00 kdeinit Running...
 7555 ? S 0:00 dcopserver [kdeinit] --nosid --suicide
 7557 ? S 0:00 klauncher [kdeinit]
 7559 ? S 0:13 kded [kdeinit]
 7572 ? S 0:00 kio_file [kdeinit] file
/tmp/ksocket-anneliese/klauncheradlnMa.slave-socket /tmp/
 7575 ? S 0:00 [kdvb-fe-0]
 7725 ? SNs 0:04 /usr/sbin/cupsd -F
 8116 ? SNs 0:00 /sbin/syslogd -u syslog
 8429 ? S 0:05 knotify [kdeinit]
 8432 ? S 0:01 /usr/bin/artsd -F 10 -S 4096 -s 60 -m artsmessage -l 3 -f

Oct 19 20:04:42 localhost syslogd 1.4.1#17ubuntu3: restart.
Oct 19 20:04:42 localhost anacron[7093]: Job `cron.daily' terminated (mailing
output)
Oct 19 20:04:42 localhost anacron[7093]: Can't find sendmail at
/usr/sbin/sendmail, not mailing output
Oct 19 20:04:42 localhost anacron[7093]: Normal exit (1 job run)
Oct 19 20:17:01 localhost /USR/SBIN/CRON[8436]: (root) CMD ( run-parts
--report /etc/cron.hourly)
Oct 19 20:22:23 localhost dhclient: DHCPREQUEST on eth0 to 192.168.2.1 port 67
Oct 19 20:22:29 localhost dhclient: DHCPREQUEST on eth0 to 192.168.2.1 port 67
Oct 19 20:22:29 localhost dhclient: DHCPACK from 192.168.2.1
Oct 19 20:22:29 localhost dhclient: bound to 192.168.2.5 -...

Read more...

Sebastien Bacher (seb128) wrote :

fixed upstream

No new upstream version yet?

Changed in kaffeine:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.