sectionsd goes crazy

[Striper]

NOKIA 2xI Avia 600 / SAT

Schaltet man auf "Das Erste" gibt sectionsd manchmal via Telnet nach einer Weile Fehlermeldungen aus. Dabei geht die Prozessorlast hoch bis zum Anschlag.

Code: Alles auswählen

$Id: sectionsd.cpp,v 1.279 2008/12/06 20:50:08 houdini Exp $
[sectionsd] Caching max 3000 events
[sectionsd] Caching 2 days
[sectionsd] Caching 12 hours Extended Text
[sectionsd] Events are old 60min after their end time
08:06:50.281 Add Channel Blacklist for channel 0x042c00016f6a, mask 0xffffffffffff
08:06:50.287 Add Channel Blacklist for channel 0x040200017023, mask 0xffffffffffff
08:06:50.307 Add Channel Blacklist for channel 0x03fc00011b64, mask 0xffffffffffff
08:06:50.312 Add Channel Blacklist for channel 0x040000012333, mask 0xffffffffffff
08:06:50.327 Add Channel Blacklist for channel 0x04000001233a, mask 0xffffffffffff
08:06:50.332 Add Channel Blacklist for channel 0x040000012346, mask 0xffffffffffff
08:06:50.338 Add Channel Blacklist for channel 0x040000012336, mask 0xffffffffffff
08:06:50.354 Add Channel Blacklist for channel 0x04000001233d, mask 0xffffffffffff
/var/tuxbox/config/mybouquets.xml: No such file or directory
~ # rdate: current time matches remote time
[timeThread] Time set via NTP, going to sleep for 1800 seconds.
08:06:52.341 dmxSDT: going to sleep...
08:07:28.160 dmxCN: going to sleep...
08:07:28.162 eit_set_update_filter, servicekey = 0x0, current version 255
(Hier kurz ins ZDF geschaltet)
08:08:15.793 dmxCN: waking up again - requested from .change()
08:08:17.544 dmxCN: going to sleep...
08:08:17.547 eit_set_update_filter, servicekey = 0x43700016d66, current version 28
(Hier in Das Erste geschaltet)
08:08:25.723 dmxCN: waking up again - requested from .change()
08:08:27.619 dmxCN: going to sleep...
08:08:27.629 eit_set_update_filter, servicekey = 0x44d00016dca, current version 3
08:08:52.754 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:08:54.804 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:08:57.033 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:08:59.105 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:01.919 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:04.333 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:06.462 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:08.545 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:11.127 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:14.084 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:16.282 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:18.309 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:20.206 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:23.283 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:25.479 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:27.618 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:29.848 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:32.314 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:35.235 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:37.577 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:39.643 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:41.575 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:44.459 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:46.693 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:48.815 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:50.873 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:53.575 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:56.497 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:09:59.931 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:10:02.999 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:10:07.472 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
08:10:11.852 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
[sectionsd] DMX::readNbytes read: Value too large for defined data type
08:10:27.738 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1
08:10:40.929 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1

Es werden nur 2 Meldungen enthaltend "filter[5]" ausgegeben und dann nichts mehr. Dies ist reproduzierbar.

Hier die zugehörige epgfilter.xml:

Code: Alles auswählen

<?xml version="1.0" encoding="UTF-8"?>
	<epgfilter is_whitelist = "0" except_current_next = "0">
		<filter serviceID="6f6a" name="CNN Int." tsid="042c" onid="0001" blacklist="1"/>
		<filter serviceID="7023" name="Sky News" tsid="0402" onid="0001" blacklist="1"/>
		<filter serviceID="1b64" name="AL JAZEERA ENG" tsid="03fc" onid="0001" blacklist="1"/>
		<filter serviceID="2333" name="CANAL ALGERIE" tsid="0400" onid="0001" blacklist="1"/>
		<filter serviceID="233a" name="TV7" tsid="0400" onid="0001" blacklist="1"/>
		<filter serviceID="2346" name="2M Maroc" tsid="0400" onid="0001" blacklist="1"/>
		<filter serviceID="2336" name="Al Masriya" tsid="0400" onid="0001" blacklist="1"/>
		<filter serviceID="233d" name="Al Jazeera" tsid="0400" onid="0001" blacklist="1"/>
	</epgfilter>

Nebenbei ist noch lästig, dass sich die Box manchmal beim Zappen auf Sky News total weghängt. Bei allen anderen "geblacklisteten" Sendern gibts keinerlei Probleme.

@seife -> HÜÜÜLFE!

[seife]

NOKIA 2xI Avia 600 / SAT

Schaltet man auf "Das Erste" gibt sectionsd manchmal via Telnet nach einer Weile Fehlermeldungen aus. Dabei geht die Prozessorlast hoch bis zum Anschlag.

Code: Alles auswählen

[sectionsd] DMX::readNbytes read: Value too large for defined data type
08:10:27.738 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1
08:10:40.929 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1

Es werden nur 2 Meldungen enthaltend "filter[5]" ausgegeben und dann nichts mehr. Dies ist reproduzierbar.

Dasselbe mit "sectionsd -d", bitte.
Die POLLERR-Meldungen sind eigentlich harmlos, sie sagen nur aus, dass die Daten schneller ankommen, als sectionsd sie verarbeiten kann. Das ist bei ARD und ZDF, besonders bei Tabelle 60/61 normal, da kommen einfach sehr viele Daten. Es mag aber sein, dass das error-handling in dmx.cpp:DMX::readNbytes() nicht optimal ist, evtl. ist dort debug-output einfügen eine gute Idee, insbesomndere der EINTR-Fall könnte evtl. unendlich busyloopen, wenn es einen Fehler beim setzen der errno gibt (was ich aber seltsam fände).

Nebenbei ist noch lästig, dass sich die Box manchmal beim Zappen auf Sky News total weghängt. Bei allen anderen "geblacklisteten" Sendern gibts keinerlei Probleme.

Da müsste sich halt mal jemand die Treiber anschauen. Bei mir tritt es nicht auf.

@seife -> HÜÜÜLFE!

Hilf dir selbst, dann... ;-)

[Striper]

*Hier stand Müll*

[Striper]

Code: Alles auswählen

# Zustand bei Aufruf: Kanal Al Jazeera International (ist auf Epgfilter-Blacklist)

~ # sectionsd -d
$Id: sectionsd.cpp,v 1.279 2008/12/06 20:50:08 houdini Exp $
[sectionsd] Caching max 3000 events
[sectionsd] Caching 2 days
[sectionsd] Caching 12 hours Extended Text
[sectionsd] Events are old 60min after their end time
09:13:06.920 Reading EPGFilters
09:13:06.923 Add Channel Blacklist for channel 0x042c00016f6a, mask 0xffffffffffff
09:13:06.926 Add Channel Blacklist for channel 0x040200017023, mask 0xffffffffffff
09:13:06.929 Add Channel Blacklist for channel 0x03fc00011b64, mask 0xffffffffffff
09:13:06.932 Add Channel Blacklist for channel 0x040000012333, mask 0xffffffffffff
09:13:06.934 Add Channel Blacklist for channel 0x04000001233a, mask 0xffffffffffff
09:13:06.937 Add Channel Blacklist for channel 0x040000012346, mask 0xffffffffffff
09:13:06.940 Add Channel Blacklist for channel 0x040000012336, mask 0xffffffffffff
09:13:06.943 Add Channel Blacklist for channel 0x04000001233d, mask 0xffffffffffff
/var/tuxbox/config/mybouquets.xml: No such file or directory
09:13:06.958 [timeThread] pid 1564 (16386) start
09:13:07.012 eitThread getschedparam: 0 pol 0, prio 0
09:13:07.014 [eitThread] pid 1566 (32771) start
09:13:07.030 [cnThread] pid 1568 (49156) start
09:13:07.033 [pptThread] pid 1569 (65541) start
09:13:07.061 [nitThread] pid 1570 (81926) start
09:13:07.085 [sdtThread] pid 1571 (98311) start
09:13:07.095 housekeeping-thread started.
09:13:07.101 mainloop getschedparam 0 policy 2 prio 1
[timeThread] Time set via NTP, going to sleep for 1800 seconds.
09:13:09.021 dmxPPT: no valid pid 0
09:13:09.023 waiting for eit_version...
09:13:09.028 dmxNIT: going to sleep...
09:13:09.040 dmxSDT: going to sleep...
09:13:10.031 [pptThread] going to sleep until wakeup...
09:13:11.220 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:11.220 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 1231920791220.896
09:13:11.235 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 14.479
09:13:11.236 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
09:13:11.242 --> 'after DMX_SET_FILTER' 7.487
09:13:13.440 [eitThread] skipping to next filter(2) (> DMX_TIMEOUT_SKIPPING)
09:13:13.441 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2198.145
09:13:13.441 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.853
09:13:13.442 changeDMX [EIT]-> 2 (0x4f/0xff) other transport stream, now/next (2 seconds)
09:13:13.446 --> 'after DMX_SET_FILTER' 4.609
09:13:15.640 [eitThread] skipping to next filter(3) (> DMX_TIMEOUT_SKIPPING)
09:13:15.641 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2194.801
09:13:15.642 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.851
09:13:15.642 changeDMX [EIT]-> 3 (0x50/0xf0) actual transport stream, scheduled2 (2 seconds)
09:13:15.646 --> 'after DMX_SET_FILTER' 4.581
09:13:17.840 [eitThread] skipping to next filter(4) (> DMX_TIMEOUT_SKIPPING)
09:13:17.841 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2194.602
09:13:17.842 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.852
09:13:17.842 changeDMX [EIT]-> 4 (0x60/0xf1) other transport stream, scheduled 1/2 (2 seconds)
09:13:17.846 --> 'after DMX_SET_FILTER' 4.713
09:13:20.040 [eitThread] skipping to next filter(5) (> DMX_TIMEOUT_SKIPPING)
09:13:20.041 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2194.143
09:13:20.041 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.860
09:13:20.042 changeDMX [EIT]-> 5 (0x61/0xf1) other transport stream, scheduled 2/2 (3 seconds)
09:13:20.046 --> 'after DMX_SET_FILTER' 4.505
09:13:22.242 dmxEIT: going to sleep for 3600 seconds...
#######################################
# (Hier umgeschaltet auf "Das Erste") #
#######################################
09:13:32.570 Connection from UDS
09:13:32.572 version: 5, cmd: 17, numbytes: 1
09:13:32.572 data length: 8
09:13:32.573 commandCurrentNextInfoChannelID
09:13:32.574 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.575 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:32.600 Connection from UDS
09:13:32.601 version: 5, cmd: 17, numbytes: 1
09:13:32.602 data length: 8
09:13:32.603 commandCurrentNextInfoChannelID
09:13:32.603 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.604 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:34.280 Connection from UDS
09:13:34.281 version: 5, cmd: 25, numbytes: 1
09:13:34.282 data length: 16
09:13:34.283 commandserviceChanged
09:13:34.283 [sectionsd] commandserviceChanged: Service changed to      44d00016dca
09:13:34.291 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 14245.291
09:13:34.292 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.869
09:13:34.293 changeDMX [12]-> 0 (0x4e/0xff) (25 seconds)
09:13:34.295 --> 'after DMX_SET_FILTER' 2.839
09:13:34.301 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 5.905
09:13:34.302 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.800
09:13:34.302 changeDMX [EIT]-> 0 (0x0/0x0) dummy filter (14 seconds)
09:13:34.306 --> 'after DMX_SET_FILTER' 4.186
09:13:34.307 [sectionsd] commandserviceChanged: END!!
09:13:34.309 dmxEIT: waking up again - requested from .change()
09:13:34.312 waiting for eit_version...
09:13:34.390 Connection from UDS
09:13:34.391 version: 5, cmd: 17, numbytes: 1
09:13:34.392 data length: 8
09:13:34.393 commandCurrentNextInfoChannelID
09:13:34.393 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.394 !myCurrentEvent 09:13:34.395 !myNextEvent 09:13:34.395 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.396 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.420 Connection from UDS
09:13:34.421 version: 5, cmd: 17, numbytes: 1
09:13:34.422 data length: 8
09:13:34.423 commandCurrentNextInfoChannelID
09:13:34.423 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.424 !myCurrentEvent 09:13:34.425 !myNextEvent 09:13:34.425 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.426 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.450 Connection from UDS
09:13:34.451 version: 5, cmd: 17, numbytes: 1
09:13:34.452 data length: 8
09:13:34.453 commandCurrentNextInfoChannelID
09:13:34.453 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.454 !myCurrentEvent 09:13:34.455 !myNextEvent 09:13:34.455 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.456 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.480 Connection from UDS
09:13:34.481 version: 5, cmd: 30, numbytes: 1
09:13:34.482 data length: 2
09:13:34.483 commandSetPrivatePid
09:13:34.600 EIT old: 255 new version: 23
09:13:34.605 addevent-cn: added running (4) event 0x4cd2 'Rote Rosen'
09:13:34.718 [cnThread] got current_next (0x1) - sending event!
09:13:35.541 addevent-cn: added next    (1) event 0x4cd5 'ARD-Wetterschau'
09:13:35.607 [cnThread] got current_next (0x3) - sending event!
09:13:35.609 dmxCN: going to sleep...
09:13:35.614 eit_set_update_filter, servicekey = 0x44d00016dca, current version 23
09:13:36.370 Connection from UDS
09:13:36.371 version: 5, cmd: 17, numbytes: 1
09:13:36.372 data length: 8
09:13:36.373 commandCurrentNextInfoChannelID
09:13:36.373 [sectionsd] Request of current/next information for      44d00016dca
09:13:36.374 currentEvt: 'Rote Rosen' (4cd2) nextEvt: 'ARD-Wetterschau' (4cd5) flag: 0x15
09:13:36.430 Connection from UDS
09:13:36.431 version: 5, cmd: 20, numbytes: 1
09:13:36.432 data length: 8
09:13:36.433 commandComponentTagsUniqueKey
09:13:36.433 Request of ComponentTags for 0x44d00016dca4cd2
09:13:36.434 ComponentTags found.
09:13:36.435 components.size 4
09:13:36.435  16:9
09:13:36.436  stereo
09:13:36.436  Dolby
09:13:36.437  Audio Description
09:13:36.600 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:36.600 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2294.594
09:13:36.601 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.844
09:13:36.602 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
09:13:36.606 --> 'after DMX_SET_FILTER' 4.298
09:13:47.275 [eitThread] skipping to next filter(2) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:13:47.277 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 10671.956
09:13:47.279 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.757
09:13:47.281 changeDMX [EIT]-> 2 (0x4f/0xff) other transport stream, now/next (11 seconds)
09:13:47.287 --> 'after DMX_SET_FILTER' 7.274
09:14:07.900 [eitThread] skipping to next filter(3) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:14:07.902 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 20615.145
09:14:07.903 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.778
09:14:07.905 changeDMX [EIT]-> 3 (0x50/0xf0) actual transport stream, scheduled2 (20 seconds)
09:14:07.911 --> 'after DMX_SET_FILTER' 7.409
09:14:08.110 [eitThread] skipping to next filter(4) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:14:08.112 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 201.245
09:14:08.114 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.746
09:14:08.115 changeDMX [EIT]-> 4 (0x60/0xf1) other transport stream, scheduled 1/2 (1 seconds)
09:14:08.121 --> 'after DMX_SET_FILTER' 7.521
09:14:10.552 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:10.556 dmx.read rc: -1 - filter: 60
09:14:13.543 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:13.546 dmx.read rc: -1 - filter: 60
09:14:15.776 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:15.779 dmx.read rc: -1 - filter: 60
09:14:17.866 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:17.869 dmx.read rc: -1 - filter: 60
09:14:19.917 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:19.920 dmx.read rc: -1 - filter: 60
09:14:23.005 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:23.008 dmx.read rc: -1 - filter: 60
09:14:25.193 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:25.196 dmx.read rc: -1 - filter: 60
09:14:27.373 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:27.376 dmx.read rc: -1 - filter: 60
09:14:29.431 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:29.434 dmx.read rc: -1 - filter: 60
09:14:32.131 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:32.134 dmx.read rc: -1 - filter: 60
09:14:35.079 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:35.082 dmx.read rc: -1 - filter: 60
09:14:37.231 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:37.307 dmx.read rc: -1 - filter: 60
09:14:39.363 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:39.366 dmx.read rc: -1 - filter: 60
09:14:41.404 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:41.407 dmx.read rc: -1 - filter: 60
09:14:44.415 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:44.418 dmx.read rc: -1 - filter: 60
09:14:46.483 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:46.486 dmx.read rc: -1 - filter: 60
09:14:48.789 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:48.793 dmx.read rc: -1 - filter: 60
09:14:51.064 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:51.067 dmx.read rc: -1 - filter: 60
09:14:55.175 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:55.195 dmx.read rc: -1 - filter: 60
09:14:58.422 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:58.425 dmx.read rc: -1 - filter: 60
09:15:01.395 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:01.412 dmx.read rc: -1 - filter: 60
09:15:06.688 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:06.692 dmx.read rc: -1 - filter: 60
09:15:10.534 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:10.538 dmx.read rc: -1 - filter: 60
09:15:17.547 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:17.551 dmx.read rc: -1 - filter: 60
09:15:36.763 [eitThread] skipping to next filter(5) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:15:36.765 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 88643.906
09:15:36.767 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.927
09:15:36.769 changeDMX [EIT]-> 5 (0x61/0xf1) other transport stream, scheduled 2/2 (88 seconds)
09:15:36.775 --> 'after DMX_SET_FILTER' 7.344
09:15:47.993 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1
09:15:47.996 dmx.read rc: -1 - filter: 61
09:16:08.456 dmxEIT: going to sleep for 3600 seconds...

Ich hab dann noch ein wenig mit der Buffergröße rumgespielt. Geht man statt 320 auf 512

Code: Alles auswählen

static DMX dmxEIT(0x12, 512);

werden die POLLERR weniger. Auch dieser Fehler

Code: Alles auswählen

[sectionsd] DMX::readNbytes read: Value too large for defined data type

ist dann nicht mehr aufgetreten. Evtl. aber auch nur Zufall. Noch höhere Bufferwerte ballern die Ramauslastung dann schon so enorm nach oben das dies m.M.n. einfach keinen Sinn hat.

Könnte (ich bin zu blöd dafür) man da gegen die hohe CPU Last irgend ein throttle einbauen?

[seife]

Code: Alles auswählen

# Zustand bei Aufruf: Kanal Al Jazeera International (ist auf Epgfilter-Blacklist)

~ # sectionsd -d
$Id: sectionsd.cpp,v 1.279 2008/12/06 20:50:08 houdini Exp $
[sectionsd] Caching max 3000 events
[sectionsd] Caching 2 days
[sectionsd] Caching 12 hours Extended Text
[sectionsd] Events are old 60min after their end time
09:13:06.920 Reading EPGFilters
09:13:06.923 Add Channel Blacklist for channel 0x042c00016f6a, mask 0xffffffffffff
09:13:06.926 Add Channel Blacklist for channel 0x040200017023, mask 0xffffffffffff
09:13:06.929 Add Channel Blacklist for channel 0x03fc00011b64, mask 0xffffffffffff
09:13:06.932 Add Channel Blacklist for channel 0x040000012333, mask 0xffffffffffff
09:13:06.934 Add Channel Blacklist for channel 0x04000001233a, mask 0xffffffffffff
09:13:06.937 Add Channel Blacklist for channel 0x040000012346, mask 0xffffffffffff
09:13:06.940 Add Channel Blacklist for channel 0x040000012336, mask 0xffffffffffff
09:13:06.943 Add Channel Blacklist for channel 0x04000001233d, mask 0xffffffffffff
/var/tuxbox/config/mybouquets.xml: No such file or directory
09:13:06.958 [timeThread] pid 1564 (16386) start
09:13:07.012 eitThread getschedparam: 0 pol 0, prio 0
09:13:07.014 [eitThread] pid 1566 (32771) start
09:13:07.030 [cnThread] pid 1568 (49156) start
09:13:07.033 [pptThread] pid 1569 (65541) start
09:13:07.061 [nitThread] pid 1570 (81926) start
09:13:07.085 [sdtThread] pid 1571 (98311) start
09:13:07.095 housekeeping-thread started.
09:13:07.101 mainloop getschedparam 0 policy 2 prio 1
[timeThread] Time set via NTP, going to sleep for 1800 seconds.
09:13:09.021 dmxPPT: no valid pid 0
09:13:09.023 waiting for eit_version...
09:13:09.028 dmxNIT: going to sleep...
09:13:09.040 dmxSDT: going to sleep...
09:13:10.031 [pptThread] going to sleep until wakeup...
09:13:11.220 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:11.220 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 1231920791220.896
09:13:11.235 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 14.479
09:13:11.236 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
...
09:13:22.242 dmxEIT: going to sleep for 3600 seconds...

Eigentlich dürfte der EIT thread gar nicht laufen, wenn der Sender in der Blacklist ist. Das Problem ist aber, dass der sectionsd bis zum neutrino-neustart nicht weiss, auf welchem Sender er ist... Da muss ich mir mal was einfallen lassen.

Code: Alles auswählen

#######################################
# (Hier umgeschaltet auf "Das Erste") #
#######################################
09:13:32.570 Connection from UDS
09:13:32.572 version: 5, cmd: 17, numbytes: 1
09:13:32.572 data length: 8
09:13:32.573 commandCurrentNextInfoChannelID
09:13:32.574 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.575 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:32.600 Connection from UDS
09:13:32.601 version: 5, cmd: 17, numbytes: 1
09:13:32.602 data length: 8
09:13:32.603 commandCurrentNextInfoChannelID
09:13:32.603 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.604 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:34.280 Connection from UDS
09:13:34.281 version: 5, cmd: 25, numbytes: 1
09:13:34.282 data length: 16
09:13:34.283 commandserviceChanged
09:13:34.283 [sectionsd] commandserviceChanged: Service changed to      44d00016dca
09:13:34.291 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 14245.291
09:13:34.292 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.869
09:13:34.293 changeDMX [12]-> 0 (0x4e/0xff) (25 seconds)
09:13:34.295 --> 'after DMX_SET_FILTER' 2.839
09:13:34.301 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 5.905
09:13:34.302 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.800
09:13:34.302 changeDMX [EIT]-> 0 (0x0/0x0) dummy filter (14 seconds)
09:13:34.306 --> 'after DMX_SET_FILTER' 4.186
09:13:34.307 [sectionsd] commandserviceChanged: END!!
09:13:34.309 dmxEIT: waking up again - requested from .change()
09:13:34.312 waiting for eit_version...
09:13:34.390 Connection from UDS
09:13:34.391 version: 5, cmd: 17, numbytes: 1
09:13:34.392 data length: 8
09:13:34.393 commandCurrentNextInfoChannelID
09:13:34.393 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.394 !myCurrentEvent 09:13:34.395 !myNextEvent 09:13:34.395 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.396 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.420 Connection from UDS
09:13:34.421 version: 5, cmd: 17, numbytes: 1
09:13:34.422 data length: 8
09:13:34.423 commandCurrentNextInfoChannelID
09:13:34.423 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.424 !myCurrentEvent 09:13:34.425 !myNextEvent 09:13:34.425 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.426 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.450 Connection from UDS
09:13:34.451 version: 5, cmd: 17, numbytes: 1
09:13:34.452 data length: 8
09:13:34.453 commandCurrentNextInfoChannelID
09:13:34.453 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.454 !myCurrentEvent 09:13:34.455 !myNextEvent 09:13:34.455 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.456 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.480 Connection from UDS
09:13:34.481 version: 5, cmd: 30, numbytes: 1
09:13:34.482 data length: 2
09:13:34.483 commandSetPrivatePid
09:13:34.600 EIT old: 255 new version: 23
09:13:34.605 addevent-cn: added running (4) event 0x4cd2 'Rote Rosen'
09:13:34.718 [cnThread] got current_next (0x1) - sending event!
09:13:35.541 addevent-cn: added next    (1) event 0x4cd5 'ARD-Wetterschau'
09:13:35.607 [cnThread] got current_next (0x3) - sending event!
09:13:35.609 dmxCN: going to sleep...
09:13:35.614 eit_set_update_filter, servicekey = 0x44d00016dca, current version 23
09:13:36.370 Connection from UDS
09:13:36.371 version: 5, cmd: 17, numbytes: 1
09:13:36.372 data length: 8
09:13:36.373 commandCurrentNextInfoChannelID
09:13:36.373 [sectionsd] Request of current/next information for      44d00016dca
09:13:36.374 currentEvt: 'Rote Rosen' (4cd2) nextEvt: 'ARD-Wetterschau' (4cd5) flag: 0x15
09:13:36.430 Connection from UDS
09:13:36.431 version: 5, cmd: 20, numbytes: 1
09:13:36.432 data length: 8
09:13:36.433 commandComponentTagsUniqueKey
09:13:36.433 Request of ComponentTags for 0x44d00016dca4cd2
09:13:36.434 ComponentTags found.
09:13:36.435 components.size 4
09:13:36.435  16:9
09:13:36.436  stereo
09:13:36.436  Dolby
09:13:36.437  Audio Description
09:13:36.600 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:36.600 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2294.594
09:13:36.601 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.844
09:13:36.602 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
09:13:36.606 --> 'after DMX_SET_FILTER' 4.298
09:13:47.275 [eitThread] skipping to next filter(2) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:13:47.277 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 10671.956
09:13:47.279 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.757
09:13:47.281 changeDMX [EIT]-> 2 (0x4f/0xff) other transport stream, now/next (11 seconds)
09:13:47.287 --> 'after DMX_SET_FILTER' 7.274
09:14:07.900 [eitThread] skipping to next filter(3) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:14:07.902 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 20615.145
09:14:07.903 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.778
09:14:07.905 changeDMX [EIT]-> 3 (0x50/0xf0) actual transport stream, scheduled2 (20 seconds)
09:14:07.911 --> 'after DMX_SET_FILTER' 7.409
09:14:08.110 [eitThread] skipping to next filter(4) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:14:08.112 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 201.245
09:14:08.114 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.746
09:14:08.115 changeDMX [EIT]-> 4 (0x60/0xf1) other transport stream, scheduled 1/2 (1 seconds)
09:14:08.121 --> 'after DMX_SET_FILTER' 7.521
09:14:10.552 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:10.556 dmx.read rc: -1 - filter: 60
...
09:15:10.534 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:10.538 dmx.read rc: -1 - filter: 60
09:15:17.547 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:17.551 dmx.read rc: -1 - filter: 60
09:15:36.763 [eitThread] skipping to next filter(5) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:15:36.765 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 88643.906
09:15:36.767 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.927
09:15:36.769 changeDMX [EIT]-> 5 (0x61/0xf1) other transport stream, scheduled 2/2 (88 seconds)
09:15:36.775 --> 'after DMX_SET_FILTER' 7.344
09:15:47.993 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1
09:15:47.996 dmx.read rc: -1 - filter: 61
09:16:08.456 dmxEIT: going to sleep for 3600 seconds...

Ab hier sollte dann auch die CPU-Last wieder weg sein. Oder?

Ich hab dann noch ein wenig mit der Buffergröße rumgespielt. Geht man statt 320 auf 512

Code: Alles auswählen

static DMX dmxEIT(0x12, 512);

werden die POLLERR weniger. Auch dieser Fehler

Code: Alles auswählen

[sectionsd] DMX::readNbytes read: Value too large for defined data type

ist dann nicht mehr aufgetreten. Evtl. aber auch nur Zufall. Noch höhere Bufferwerte ballern die Ramauslastung dann schon so enorm nach oben das dies m.M.n. einfach keinen Sinn hat.

Das ist tatsächlich Zufall. Ich habe mit verschiedenen Werten rumprobiert (ist glaube ich sogar im CVS nachzulesen ) und es kamen immer ein paar overflows. Die Box ist einfach zu langsam (bzw. sectionsd nicht genug optimiert), um die Daten in der Geschwindigkeit einzulesen, wie sie ankommen. Auf der dm500 kommt das nicht vor . Die Fehler sind aber harmlos, die Daten werden einfach beim nächsten Mal eingelesen. Ausserdem sind es IIUC sowieso "nur" Daten für andere Transponder.
Es ist auch zu bedenken dass die DMX buffergrösse Kernel-Speicher ist, damit sollte man besonders sparsam umgehen.
Übrigens hat enigma genau dasselbe Problem, aber auch dort stört es nicht wirklich.

Könnte (ich bin zu blöd dafür) man da gegen die hohe CPU Last irgend ein throttle einbauen?

Klar. Dann bekommst du aber noch mehr POLLERRs und overflows.
Bestimmt könnte man den Code optimieren, um die Effizienz zu steigern und die CPU-Last zu verringern. Ich weiss auch nicht, wie effizient die Verwendung von C++-konstrukten wie map und vector hier ist, allerdings will ich den sectionsd auch nicht auf handgestrickte Pointerlisten umbauen ;-)

Die einzige wichtige Frage ist also nun: bleibt die CPU-Last dauerhaft hoch (bug) oder geht sie wieder runter, wenn der EIT-Thread fertig ist (kein bug).

[seife]

Code: Alles auswählen

# Zustand bei Aufruf: Kanal Al Jazeera International (ist auf Epgfilter-Blacklist)

~ # sectionsd -d
$Id: sectionsd.cpp,v 1.279 2008/12/06 20:50:08 houdini Exp $
[sectionsd] Caching max 3000 events
[sectionsd] Caching 2 days
[sectionsd] Caching 12 hours Extended Text
[sectionsd] Events are old 60min after their end time
09:13:06.920 Reading EPGFilters
09:13:06.923 Add Channel Blacklist for channel 0x042c00016f6a, mask 0xffffffffffff
09:13:06.926 Add Channel Blacklist for channel 0x040200017023, mask 0xffffffffffff
09:13:06.929 Add Channel Blacklist for channel 0x03fc00011b64, mask 0xffffffffffff
09:13:06.932 Add Channel Blacklist for channel 0x040000012333, mask 0xffffffffffff
09:13:06.934 Add Channel Blacklist for channel 0x04000001233a, mask 0xffffffffffff
09:13:06.937 Add Channel Blacklist for channel 0x040000012346, mask 0xffffffffffff
09:13:06.940 Add Channel Blacklist for channel 0x040000012336, mask 0xffffffffffff
09:13:06.943 Add Channel Blacklist for channel 0x04000001233d, mask 0xffffffffffff
/var/tuxbox/config/mybouquets.xml: No such file or directory
09:13:06.958 [timeThread] pid 1564 (16386) start
09:13:07.012 eitThread getschedparam: 0 pol 0, prio 0
09:13:07.014 [eitThread] pid 1566 (32771) start
09:13:07.030 [cnThread] pid 1568 (49156) start
09:13:07.033 [pptThread] pid 1569 (65541) start
09:13:07.061 [nitThread] pid 1570 (81926) start
09:13:07.085 [sdtThread] pid 1571 (98311) start
09:13:07.095 housekeeping-thread started.
09:13:07.101 mainloop getschedparam 0 policy 2 prio 1
[timeThread] Time set via NTP, going to sleep for 1800 seconds.
09:13:09.021 dmxPPT: no valid pid 0
09:13:09.023 waiting for eit_version...
09:13:09.028 dmxNIT: going to sleep...
09:13:09.040 dmxSDT: going to sleep...
09:13:10.031 [pptThread] going to sleep until wakeup...
09:13:11.220 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:11.220 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 1231920791220.896
09:13:11.235 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 14.479
09:13:11.236 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
...
09:13:22.242 dmxEIT: going to sleep for 3600 seconds...

Eigentlich dürfte der EIT thread gar nicht laufen, wenn der Sender in der Blacklist ist. Das Problem ist aber, dass der sectionsd bis zum neutrino-neustart nicht weiss, auf welchem Sender er ist... Da muss ich mir mal was einfallen lassen.

Code: Alles auswählen

#######################################
# (Hier umgeschaltet auf "Das Erste") #
#######################################
09:13:32.570 Connection from UDS
09:13:32.572 version: 5, cmd: 17, numbytes: 1
09:13:32.572 data length: 8
09:13:32.573 commandCurrentNextInfoChannelID
09:13:32.574 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.575 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:32.600 Connection from UDS
09:13:32.601 version: 5, cmd: 17, numbytes: 1
09:13:32.602 data length: 8
09:13:32.603 commandCurrentNextInfoChannelID
09:13:32.603 [sectionsd] Request of current/next information for      44d00016dca
09:13:32.604 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x20
09:13:34.280 Connection from UDS
09:13:34.281 version: 5, cmd: 25, numbytes: 1
09:13:34.282 data length: 16
09:13:34.283 commandserviceChanged
09:13:34.283 [sectionsd] commandserviceChanged: Service changed to      44d00016dca
09:13:34.291 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 14245.291
09:13:34.292 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.869
09:13:34.293 changeDMX [12]-> 0 (0x4e/0xff) (25 seconds)
09:13:34.295 --> 'after DMX_SET_FILTER' 2.839
09:13:34.301 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 5.905
09:13:34.302 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.800
09:13:34.302 changeDMX [EIT]-> 0 (0x0/0x0) dummy filter (14 seconds)
09:13:34.306 --> 'after DMX_SET_FILTER' 4.186
09:13:34.307 [sectionsd] commandserviceChanged: END!!
09:13:34.309 dmxEIT: waking up again - requested from .change()
09:13:34.312 waiting for eit_version...
09:13:34.390 Connection from UDS
09:13:34.391 version: 5, cmd: 17, numbytes: 1
09:13:34.392 data length: 8
09:13:34.393 commandCurrentNextInfoChannelID
09:13:34.393 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.394 !myCurrentEvent 09:13:34.395 !myNextEvent 09:13:34.395 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.396 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.420 Connection from UDS
09:13:34.421 version: 5, cmd: 17, numbytes: 1
09:13:34.422 data length: 8
09:13:34.423 commandCurrentNextInfoChannelID
09:13:34.423 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.424 !myCurrentEvent 09:13:34.425 !myNextEvent 09:13:34.425 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.426 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.450 Connection from UDS
09:13:34.451 version: 5, cmd: 17, numbytes: 1
09:13:34.452 data length: 8
09:13:34.453 commandCurrentNextInfoChannelID
09:13:34.453 [sectionsd] Request of current/next information for      44d00016dca
09:13:34.454 !myCurrentEvent 09:13:34.455 !myNextEvent 09:13:34.455 commandCurrentNextInfoChannelID change2 flag: 0x08
09:13:34.456 currentEvt: '' (0000) nextEvt: '' (0000) flag: 0x28
09:13:34.480 Connection from UDS
09:13:34.481 version: 5, cmd: 30, numbytes: 1
09:13:34.482 data length: 2
09:13:34.483 commandSetPrivatePid
09:13:34.600 EIT old: 255 new version: 23
09:13:34.605 addevent-cn: added running (4) event 0x4cd2 'Rote Rosen'
09:13:34.718 [cnThread] got current_next (0x1) - sending event!
09:13:35.541 addevent-cn: added next    (1) event 0x4cd5 'ARD-Wetterschau'
09:13:35.607 [cnThread] got current_next (0x3) - sending event!
09:13:35.609 dmxCN: going to sleep...
09:13:35.614 eit_set_update_filter, servicekey = 0x44d00016dca, current version 23
09:13:36.370 Connection from UDS
09:13:36.371 version: 5, cmd: 17, numbytes: 1
09:13:36.372 data length: 8
09:13:36.373 commandCurrentNextInfoChannelID
09:13:36.373 [sectionsd] Request of current/next information for      44d00016dca
09:13:36.374 currentEvt: 'Rote Rosen' (4cd2) nextEvt: 'ARD-Wetterschau' (4cd5) flag: 0x15
09:13:36.430 Connection from UDS
09:13:36.431 version: 5, cmd: 20, numbytes: 1
09:13:36.432 data length: 8
09:13:36.433 commandComponentTagsUniqueKey
09:13:36.433 Request of ComponentTags for 0x44d00016dca4cd2
09:13:36.434 ComponentTags found.
09:13:36.435 components.size 4
09:13:36.435  16:9
09:13:36.436  stereo
09:13:36.436  Dolby
09:13:36.437  Audio Description
09:13:36.600 [eitThread] skipping to next filter(1) (> DMX_TIMEOUT_SKIPPING)
09:13:36.600 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 2294.594
09:13:36.601 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 0.844
09:13:36.602 changeDMX [EIT]-> 1 (0x50/0xff) actual transport stream, scheduled (2 seconds)
09:13:36.606 --> 'after DMX_SET_FILTER' 4.298
09:13:47.275 [eitThread] skipping to next filter(2) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:13:47.277 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 10671.956
09:13:47.279 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.757
09:13:47.281 changeDMX [EIT]-> 2 (0x4f/0xff) other transport stream, now/next (11 seconds)
09:13:47.287 --> 'after DMX_SET_FILTER' 7.274
09:14:07.900 [eitThread] skipping to next filter(3) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:14:07.902 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 20615.145
09:14:07.903 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.778
09:14:07.905 changeDMX [EIT]-> 3 (0x50/0xf0) actual transport stream, scheduled2 (20 seconds)
09:14:07.911 --> 'after DMX_SET_FILTER' 7.409
09:14:08.110 [eitThread] skipping to next filter(4) (> DMX_HAS_ALL_CURRENT_SECTIONS_SKIPPING)
09:14:08.112 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 201.245
09:14:08.114 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.746
09:14:08.115 changeDMX [EIT]-> 4 (0x60/0xf1) other transport stream, scheduled 1/2 (1 seconds)
09:14:08.121 --> 'after DMX_SET_FILTER' 7.521
09:14:10.552 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:14:10.556 dmx.read rc: -1 - filter: 60
...
09:15:10.534 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:10.538 dmx.read rc: -1 - filter: 60
09:15:17.547 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[4] filter 0x60 mask 0xf1
09:15:17.551 dmx.read rc: -1 - filter: 60
09:15:36.763 [eitThread] skipping to next filter(5) (> DMX_HAS_ALL_SECTIONS_SKIPPING)
09:15:36.765 --> 'changeDMX: before pthread_mutex_lock(&start_stop_mutex)' 88643.906
09:15:36.767 --> 'changeDMX: after pthread_mutex_lock(&start_stop_mutex)' 1.927
09:15:36.769 changeDMX [EIT]-> 5 (0x61/0xf1) other transport stream, scheduled 2/2 (88 seconds)
09:15:36.775 --> 'after DMX_SET_FILTER' 7.344
09:15:47.993 [sectionsd] DMX::readNbytes received POLLERR, pid 0x12, filter[5] filter 0x61 mask 0xf1
09:15:47.996 dmx.read rc: -1 - filter: 61
09:16:08.456 dmxEIT: going to sleep for 3600 seconds...

Ab hier sollte dann auch die CPU-Last wieder weg sein. Oder?

Ich hab dann noch ein wenig mit der Buffergröße rumgespielt. Geht man statt 320 auf 512

Code: Alles auswählen

static DMX dmxEIT(0x12, 512);

werden die POLLERR weniger. Auch dieser Fehler

Code: Alles auswählen

[sectionsd] DMX::readNbytes read: Value too large for defined data type

ist dann nicht mehr aufgetreten. Evtl. aber auch nur Zufall. Noch höhere Bufferwerte ballern die Ramauslastung dann schon so enorm nach oben das dies m.M.n. einfach keinen Sinn hat.

Das ist tatsächlich Zufall. Ich habe mit verschiedenen Werten rumprobiert (ist glaube ich sogar im CVS nachzulesen ) und es kamen immer ein paar overflows. Die Box ist einfach zu langsam (bzw. sectionsd nicht genug optimiert), um die Daten in der Geschwindigkeit einzulesen, wie sie ankommen. Auf der dm500 kommt das nicht vor . Die Fehler sind aber harmlos, die Daten werden einfach beim nächsten Mal eingelesen. Ausserdem sind es IIUC sowieso "nur" Daten für andere Transponder.
Es ist auch zu bedenken dass die DMX buffergrösse Kernel-Speicher ist, damit sollte man besonders sparsam umgehen.
Übrigens hat enigma genau dasselbe Problem, aber auch dort stört es nicht wirklich.

Könnte (ich bin zu blöd dafür) man da gegen die hohe CPU Last irgend ein throttle einbauen?

Klar. Dann bekommst du aber noch mehr POLLERRs und overflows.
Bestimmt könnte man den Code optimieren, um die Effizienz zu steigern und die CPU-Last zu verringern. Ich weiss auch nicht, wie effizient die Verwendung von C++-konstrukten wie map und vector hier ist, allerdings will ich den sectionsd auch nicht auf handgestrickte Pointerlisten umbauen ;-)

Die einzige wichtige Frage ist also nun: bleibt die CPU-Last dauerhaft hoch (bug) oder geht sie wieder runter, wenn der EIT-Thread fertig ist (kein bug).

[Striper]

Nein es ist kein Bug. Sobald die Kiste fertig ist mit den EIT-Threads geht auch die CPU Last wieder runter. Während der Bearbeitung der Threads ist die Box leider kaum bedienbar. Deshalb meine Frage wegen throttle. Das die Threadverarbeitung dann länger dauern würde, wäre mir sogar egal. Wichtiger ist das die Box bedienbar bleibt. Danke für deine Erklärungen und evtl. findest du ja noch etwas Optimierungspotential!

[seife]

mach mal den pthread_setschedparam()-Aufrufe in Zeile 8236 weg (einfach durch "rc = 0" ersetzen.
Der war damals als übler hack gegen die deadlocks reingekommen, aber ist jetzt nicht mehr notwendig, meine Kiste läuft schon sehr lange ohne . Dann wird der sectionsd vermutlich wieder freundlicher zum Scheduler sein.

[GetAway]

Während der Bearbeitung der Threads ist die Box leider kaum bedienbar.

Alternativ könntest du mal mit renice 5 spielen. Dadurch wird die Prio etwas runtergesetzt
und die "Kiste" flutscht währenddessen besser.

[Striper]

Während der Bearbeitung der Threads ist die Box leider kaum bedienbar.

Alternativ könntest du mal mit renice 5 spielen. Dadurch wird die Prio etwas runtergesetzt
und die "Kiste" flutscht währenddessen besser.

Hm, wie/wo müsste ich da was drehen?

[GetAway]

Hm, wie/wo müsste ich da was drehen?

Über Konsole eingeben:

Code: Alles auswählen

renice 5 `pidof sectionsd`

Mit "top" z.B. kannst du das anschließend überprüfen.

[seife]

Das wird nicht viel helfen, weil der sectionsd-Hauptthread immer noch ein realtime-Prozess ist, solange das pthread_setschedparam() nicht rausgenommen wird. IIUC hat der im Scheduler, egal wie weit du den reniced hast, immer noch eine höhere Prio als alle anderen Prozesse.
Ich habe damals extra deswegen ein paar sched_yield() aufrufe eingebaut, damit er nicht deadlocken und die Box in den Abgrund reissen kann.
Mag sein, dass das alles nur auf 2.6 tatsächlich was ausmacht, aber ich würde trotzdem erstmal versuchen ob es besser wird, wenn die RT-Attribute weg sind.

[Striper]

mach mal den pthread_setschedparam()-Aufrufe in Zeile 8236 weg (einfach durch "rc = 0" ersetzen.
Der war damals als übler hack gegen die deadlocks reingekommen, aber ist jetzt nicht mehr notwendig, meine Kiste läuft schon sehr lange ohne ;). Dann wird der sectionsd vermutlich wieder freundlicher zum Scheduler sein.

Hab das gestern mal versucht, jedoch konnte ich keine Änderung bemerken. Ich lass es aber trotzdem erstmal auf "rc = 0;".