Here:
wget “https://collab.osmc.tv/s/8jQFwUONJSJOLBy/download” -O kernel.deb
sudo dpkg -i kernel.deb
reboot
Thanks for your patience.
Ok i installed that kernel
osmc@vero4k:~/temp$ sudo dpkg -i kernel.deb
(Reading database … 25988 files and directories currently installed.)
Preparing to unpack kernel.deb …
Examining /etc/kernel/preinst.d/
Done.
Unpacking vero364-image-3.14.29-124-osmc:arm64 (124) over (124) …
Examining /etc/kernel/postrm.d .
Setting up vero364-image-3.14.29-124-osmc:arm64 (124) …
Running depmod.
Examining /etc/kernel/postinst.d.
run-parts: executing /etc/kernel/postinst.d/apt-auto-removal 3.14.29-124-o
mc /boot/vmlinuz-3.14.29-124-osmc
run-parts: executing /etc/kernel/postinst.d/apt-auto-removal-osmc 3.14.29-
24-osmc /boot/vmlinuz-3.14.29-124-osmc
run-parts: executing /etc/kernel/postinst.d/inform-updater 3.14.29-124-osm
/boot/vmlinuz-3.14.29-124-osmc
run-parts: executing /etc/kernel/postinst.d/upload-to-emmc 3.14.29-124-osm
/boot/vmlinuz-3.14.29-124-osmc
7+1 records in
7+1 records out
8314880 bytes (8.3 MB, 7.9 MiB) copied, 0.192424 s, 43.2 MB/s
0+1 records in
0+1 records out
83968 bytes (84 kB, 82 KiB) copied, 0.00975857 s, 8.6 MB/s
Rebooted, and tried running dropwatch again
Output looks very similar
osmc@vero4k:~/drop_watch-master/src$ ./dropwatch -l kas
Initalizing kallsyms db
dropwatch> start
Enabling monitoring…
Kernel monitoring activated.
Issue Ctrl-C to stop monitoring
1 drops at (null)+0 (0x184211c)
9 drops at (null)+0 (0x17e1fb4)
1 drops at (null)+2b5c (0x17e4b10)
1 drops at (null)+0 (0x17e1fb4)
1 drops at (null)+62338 (0x18442ec)
2 drops at (null)+3b660 (0x181d614)
2 drops at (null)+3b660 (0x181d614)
1 drops at (null)+0 (0x17b30b8)
3 drops at (null)+6a55c (0x181d614)
When i start playing live tv i see a load of drops. This happened in the space of 5-10 seconds
4 drops at (null)+0 (0x17aa5cc)
5 drops at (null)+0 (0x17aa5cc)
3 drops at (null)+0 (0x17aa5cc)
14 drops at (null)+0 (0x17aa5cc)
2 drops at (null)+0 (0x17aa5cc)
12 drops at (null)+0 (0x17aa5cc)
3 drops at (null)+0 (0x17aa5cc)
21 drops at (null)+0 (0x17aa5cc)
18 drops at (null)+0 (0x17aa5cc)
5 drops at (null)+0 (0x17aa5cc)
17 drops at (null)+0 (0x17aa5cc)
1 drops at (null)+0 (0x17aa5cc)
13 drops at (null)+0 (0x17aa5cc)
1 drops at (null)+0 (0x17aa5cc)
5 drops at (null)+0 (0x17aa5cc)
4 drops at (null)+0 (0x17aa5cc)
10 drops at (null)+0 (0x17aa5cc)
4 drops at (null)+0 (0x17aa5cc)
13 drops at (null)+0 (0x17aa5cc)
Hm. Without the function name, it’s not clear what function to check the offset against.
Investigating.
FTR I also tried running dropwatch as root:
sudo su - root
./dropwatch -l kas
But still no function names.
I built with CONFIG_KALLSYMS_ALL=y and CONFIG_DEBUG_INFO=y. I can get detailed information with addr2line on a function + offset. Not sure why dropwatch isn’t getting those functions back yet.
Sam
Hi Sam,
I’ve just taken a look at this myself. I forked the dropwatch git project and made a change to the code such that the function names are returned correctly on osmc - see here: GitHub - jahutchi/drop_watch: Monitor reasons why and where linux drops UDP packets - Fork for OSMC to resolve problem with function name not being returned
I also added the current timestamp to the output, otherwise it’s difficult to cross-check the results to the kodi logfile.
Following this I’m seeing much better output:
osmc@vero4k:~/drop_watch/src$ ./dropwatch -l kas
Initalizing kallsyms db
dropwatch> start
Enabling monitoring...
Kernel monitoring activated.
Issue Ctrl-C to stop monitoring
11:01:47 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:02:02 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:02:18 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:02:33 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:02:49 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:03:04 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:03:19 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
11:03:35 2 drops at __udp4_lib_mcast_deliver.isra.9+254 (0x181d614)
I’ll play some live streams and try and capture the output so that we can see the kodi logs and dropwatch logs for the same time frame…
I’ve reproduced the problem with dropwatch running, and here are the osmc grab-logs:
https://paste.osmc.tv/odotadoway
The problem occurred at the following times:
11:34:03.760 T:3515585280 DEBUG: CAMLCodec::Reset
11:34:07.367 T:3515585280 DEBUG: CAMLCodec::Reset
11:34:13.464 T:3515585280 DEBUG: CAMLCodec::Reset
11:36:19.533 T:3515585280 DEBUG: CAMLCodec::Reset
Here is the output from drop_watch: https://paste.osmc.tv/siwutoxinu
I had to trim the kodi log back, as it was too large to upload, so it only covers the occurrences above.
However, there were further occurrences (AML Codec resetting in the middle of a broadcast) at the following times:
12:14:07.319 T:3515585280 DEBUG: CAMLCodec::Reset
12:23:59.943 T:3515585280 DEBUG: CAMLCodec::Reset
12:24:06.479 T:3515585280 DEBUG: CAMLCodec::Reset
13:24:17.319 T:3515585280 DEBUG: CAMLCodec::Reset
13:25:10.363 T:3515585280 DEBUG: CAMLCodec::Reset
13:40:06.408 T:3515585280 DEBUG: CAMLCodec::Reset
14:14:00.718 T:3515585280 DEBUG: CAMLCodec::Reset
14:14:31.137 T:3515585280 DEBUG: CAMLCodec::Reset
14:34:10.781 T:3515585280 DEBUG: CAMLCodec::Reset
14:34:46.958 T:3515585280 DEBUG: CAMLCodec::Reset
15:01:08.175 T:3515585280 DEBUG: CAMLCodec::Reset
15:19:19.005 T:3515585280 DEBUG: CAMLCodec::Reset
Which were also covered by the drop_watch capture.
Can you check dmesg when you see those resets? Decoder is noisy, so want to see if it’s moaning when this happens
Cheers
Sam
Good job.
dmesg seems quite busy and the relevant entries are now lost from the buffer. However, doesn’t the journal contain all the same stuff as per dmesg? If so, this can be found in the logs aready supplied
Here are the entires extracted from the journal for those drop outs
Oct 30 11:33:55 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:33:55 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:33:55 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:6d6553,
Oct 30 11:33:55 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:6d7363,
Oct 30 11:33:55 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:33:57 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:33:57 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:6fb3f3,
Oct 30 11:33:57 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:33:57 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:33:57 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:701663,
Oct 30 11:33:57 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:33:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:33:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:70e953,
Oct 30 11:33:58 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:33:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:714bc3,
Oct 30 11:33:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:33:58 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:00 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:73e0b3,
Oct 30 11:34:00 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:00 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:01 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:75a2b3,
Oct 30 11:34:01 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:75b0c3,
Oct 30 11:34:01 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:03 vero4k kernel: codec: Frame parameters: Size 1920x1080
Oct 30 11:34:03 vero4k kernel: codec: interlace-bottom
Oct 30 11:34:03 vero4k kernel: codec: (Full type: 0x00008003)
Oct 30 11:34:03 vero4k kernel: codec: Bit depth: 8-bit, Colour range: limited
Oct 30 11:34:03 vero4k kernel: codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
Oct 30 11:34:03 vero4k kernel: codec: No master display info
Oct 30 11:34:03 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:03 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:778ee3,
Oct 30 11:34:03 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:03 vero4k mediacenter[19766]: [codec_pause]p->has_audio=0
Oct 30 11:34:03 vero4k mediacenter[19766]: video_pause!
Oct 30 11:34:03 vero4k mediacenter[19766]: [codec_close_cntl]video codec close return=0!
Oct 30 11:34:03 vero4k kernel: codec:video_blackout_policy_store(0)
Oct 30 11:34:03 vero4k kernel: [tsync_avevent]event:1, param 1
Oct 30 11:34:03 vero4k kernel: video pause!
Oct 30 11:34:03 vero4k kernel: codec:invalid h264pts1, reset
Oct 30 11:34:03 vero4k kernel: DI: di_receiver_event_fun , is_bypass() 0 trick_mode 0 bypass_all 0
Oct 30 11:34:03 vero4k kernel: di_receiver_event_fun: vf_notify_receiver unreg
Oct 30 11:34:03 vero4k kernel: DI: di_unreg_process unreg start 1.
Oct 30 11:34:03 vero4k kernel: codec:keep exit is di
Oct 30 11:34:03 vero4k kernel: [tsync_avevent]event:2, param 0
Oct 30 11:34:03 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:03 vero4k kernel: DI: di_unreg_process vf unreg cost 0 ms.
Oct 30 11:34:03 vero4k kernel: DI: di_unreg_process unreg stop 0.
Oct 30 11:34:03 vero4k kernel: di_uninit_buf keep cur di_buf 11 (6 2 7)
Oct 30 11:34:03 vero4k mediacenter[19766]: OPEN es DEVICE
Oct 30 11:34:03 vero4k kernel: codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
Oct 30 11:34:03 vero4k kernel: codec:vdec_create instance ffffff80063d0000, total 1
Oct 30 11:34:03 vero4k kernel: codec:Video stbuf alloced at 0000000063b00000, size = 10485760
Oct 30 11:34:03 vero4k kernel: codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
Oct 30 11:34:03 vero4k kernel: codec:vdec_init set vfm decoder ffffff80063d0000
Oct 30 11:34:03 vero4k kernel: codec:vdec_dev_reg.mem[0x64500000 -- 0x674fffff]
Oct 30 11:34:03 vero4k kernel: codec:H264 sysinfo: 1920x1080 duration=3840, pts_outside=1,
Oct 30 11:34:03 vero4k kernel: codec:vdec_request_irq ffffffc001699d78, vh264-irq
Oct 30 11:34:03 vero4k kernel: DI: di_receiver_event_fun: vframe provider reg
Oct 30 11:34:03 vero4k mediacenter[19766]: [codec_reset:1146]ret=0
Oct 30 11:34:03 vero4k kernel: set run_early_proc_fun_flag to 1
Oct 30 11:34:03 vero4k kernel: codec:vdec_init, vf_provider_name =
Oct 30 11:34:03 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:03 vero4k kernel: codec:vdec_request_irq ffffffc00168b1e8, parser
Oct 30 11:34:03 vero4k kernel: codec:video_blackout_policy_store(1)
Oct 30 11:34:03 vero4k kernel: codec:video first checkin pts = 7adaa3
Oct 30 11:34:03 vero4k kernel: codec:first check in vpts <0x2a:0x7adaa3> ok!
Oct 30 11:34:03 vero4k kernel: codec:Enter set parameter cmd1.
Oct 30 11:34:03 vero4k kernel: codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
Oct 30 11:34:03 vero4k kernel: codec:actual_dpb_size 15 max_dpb_size 3
Oct 30 11:34:03 vero4k kernel: codec:video first pts = 7adaa3
Oct 30 11:34:03 vero4k kernel: pre_de_buf_config: source change: 0x0/0/0/0=>0x8009/1920/1080/0
Oct 30 11:34:04 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback disable
Oct 30 11:34:04 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
Oct 30 11:34:04 vero4k kernel: i2s/958 same source - init spdif
Oct 30 11:34:04 vero4k kernel: aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1), stream format=1
Oct 30 11:34:04 vero4k kernel: aml_spdif_dai: set divider = 2 for i2s shared clock
Oct 30 11:34:04 vero4k kernel: aml_audio_hw: IEC958 PCM32
Oct 30 11:34:04 vero4k kernel: hdmitx: audio: aout notify rate 48000
Oct 30 11:34:04 vero4k kernel: hdmitx: audio: aout notify size 32
Oct 30 11:34:04 vero4k kernel: hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
Oct 30 11:34:04 vero4k kernel: hdmitx: audio: no update
Oct 30 11:34:04 vero4k kernel: vpts to scr, apts = 0x0, vpts = 0x7adaa3
Oct 30 11:34:04 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:7ae8b3,
Oct 30 11:34:04 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:04 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback enable
Oct 30 11:34:04 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
Oct 30 11:34:04 vero4k kernel: DI: recycle_keep_buffer recycle keep cur di_buf 11 (
Oct 30 11:34:04 vero4k kernel: DI: 6
Oct 30 11:34:04 vero4k kernel: DI: 2
Oct 30 11:34:04 vero4k kernel: DI: 7
Oct 30 11:34:04 vero4k kernel: DI: )
Oct 30 11:34:05 vero4k kernel: codec:finished correct frame dur
Oct 30 11:34:05 vero4k kernel: codec: new=3840,old_duration=3840,cnt=25
Oct 30 11:34:05 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:7be5d3,
Oct 30 11:34:06 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:06 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:06 vero4k kernel: codec:fix_frame_rate mode play
Oct 30 11:34:07 vero4k mediacenter[19766]: [codec_pause]p->has_audio=0
Oct 30 11:34:07 vero4k mediacenter[19766]: video_pause!
Oct 30 11:34:07 vero4k mediacenter[19766]: [codec_close_cntl]video codec close return=0!
Oct 30 11:34:07 vero4k kernel: codec:video_blackout_policy_store(0)
Oct 30 11:34:07 vero4k kernel: [tsync_avevent]event:1, param 1
Oct 30 11:34:07 vero4k kernel: video pause!
Oct 30 11:34:07 vero4k kernel: DI: di_receiver_event_fun , is_bypass() 0 trick_mode 0 bypass_all 0
Oct 30 11:34:07 vero4k kernel: di_receiver_event_fun: vf_notify_receiver unreg
Oct 30 11:34:07 vero4k kernel: DI: di_unreg_process unreg start 1.
Oct 30 11:34:07 vero4k kernel: codec:keep exit is di
Oct 30 11:34:07 vero4k kernel: [tsync_avevent]event:2, param 0
Oct 30 11:34:07 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:07 vero4k kernel: DI: di_unreg_process vf unreg cost 0 ms.
Oct 30 11:34:07 vero4k kernel: DI: di_unreg_process unreg stop 0.
Oct 30 11:34:07 vero4k kernel: di_uninit_buf keep cur di_buf 4 (0 6 1)
Oct 30 11:34:07 vero4k mediacenter[19766]: OPEN es DEVICE
Oct 30 11:34:07 vero4k kernel: codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
Oct 30 11:34:07 vero4k kernel: codec:vdec_create instance ffffff8006401000, total 1
Oct 30 11:34:07 vero4k kernel: codec:Video stbuf alloced at 0000000063b00000, size = 10485760
Oct 30 11:34:07 vero4k kernel: codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
Oct 30 11:34:07 vero4k kernel: codec:vdec_init set vfm decoder ffffff8006401000
Oct 30 11:34:07 vero4k kernel: codec:vdec_dev_reg.mem[0x64500000 -- 0x674fffff]
Oct 30 11:34:07 vero4k kernel: codec:H264 sysinfo: 1920x1080 duration=3840, pts_outside=1,
Oct 30 11:34:07 vero4k kernel: codec:vdec_request_irq ffffffc001699d78, vh264-irq
Oct 30 11:34:07 vero4k kernel: DI: di_receiver_event_fun: vframe provider reg
Oct 30 11:34:07 vero4k mediacenter[19766]: [codec_reset:1146]ret=0
Oct 30 11:34:07 vero4k kernel: set run_early_proc_fun_flag to 1
Oct 30 11:34:07 vero4k kernel: codec:vdec_init, vf_provider_name =
Oct 30 11:34:07 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:07 vero4k kernel: codec:vdec_request_irq ffffffc00168b1e8, parser
Oct 30 11:34:07 vero4k kernel: codec:video_blackout_policy_store(1)
Oct 30 11:34:07 vero4k kernel: codec:video first checkin pts = 807503
Oct 30 11:34:07 vero4k kernel: codec:first check in vpts <0x2a:0x807503> ok!
Oct 30 11:34:07 vero4k kernel: codec:Enter set parameter cmd1.
Oct 30 11:34:07 vero4k kernel: codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
Oct 30 11:34:07 vero4k kernel: codec:actual_dpb_size 15 max_dpb_size 3
Oct 30 11:34:07 vero4k kernel: codec:video first pts = 807503
Oct 30 11:34:07 vero4k kernel: pre_de_buf_config: source change: 0x0/0/0/0=>0x8009/1920/1080/0
Oct 30 11:34:07 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback disable
Oct 30 11:34:07 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
Oct 30 11:34:07 vero4k kernel: i2s/958 same source - init spdif
Oct 30 11:34:07 vero4k kernel: aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1), stream format=1
Oct 30 11:34:07 vero4k kernel: aml_spdif_dai: set divider = 2 for i2s shared clock
Oct 30 11:34:07 vero4k kernel: aml_audio_hw: IEC958 PCM32
Oct 30 11:34:07 vero4k kernel: hdmitx: audio: aout notify rate 48000
Oct 30 11:34:07 vero4k kernel: hdmitx: audio: aout notify size 32
Oct 30 11:34:07 vero4k kernel: hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
Oct 30 11:34:07 vero4k kernel: hdmitx: audio: no update
Oct 30 11:34:07 vero4k kernel: vpts to scr, apts = 0x0, vpts = 0x807503
Oct 30 11:34:07 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:808313,
Oct 30 11:34:07 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:07 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback enable
Oct 30 11:34:07 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
Oct 30 11:34:08 vero4k kernel: DI: recycle_keep_buffer recycle keep cur di_buf 4 (
Oct 30 11:34:08 vero4k kernel: DI: 0
Oct 30 11:34:08 vero4k kernel: DI: 6
Oct 30 11:34:08 vero4k kernel: DI: 1
Oct 30 11:34:08 vero4k kernel: DI: )
Oct 30 11:34:09 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:09 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:80c963,
Oct 30 11:34:09 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:09 vero4k kernel: codec:finished correct frame dur
Oct 30 11:34:09 vero4k kernel: codec: new=3840,old_duration=3840,cnt=25
Oct 30 11:34:09 vero4k kernel: codec:fix_frame_rate mode play
Oct 30 11:34:10 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:10 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:824513,
Oct 30 11:34:10 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:13 vero4k mediacenter[19766]: [codec_pause]p->has_audio=0
Oct 30 11:34:13 vero4k mediacenter[19766]: video_pause!
Oct 30 11:34:13 vero4k mediacenter[19766]: [codec_close_cntl]video codec close return=0!
Oct 30 11:34:13 vero4k kernel: codec:video_blackout_policy_store(0)
Oct 30 11:34:13 vero4k kernel: [tsync_avevent]event:1, param 1
Oct 30 11:34:13 vero4k kernel: video pause!
Oct 30 11:34:13 vero4k kernel: DI: di_receiver_event_fun , is_bypass() 0 trick_mode 0 bypass_all 0
Oct 30 11:34:13 vero4k kernel: di_receiver_event_fun: vf_notify_receiver unreg
Oct 30 11:34:13 vero4k kernel: DI: di_unreg_process unreg start 1.
Oct 30 11:34:13 vero4k kernel: codec:keep exit is di
Oct 30 11:34:13 vero4k kernel: [tsync_avevent]event:2, param 0
Oct 30 11:34:13 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:13 vero4k kernel: DI: di_unreg_process vf unreg cost 0 ms.
Oct 30 11:34:13 vero4k kernel: DI: di_unreg_process unreg stop 0.
Oct 30 11:34:13 vero4k kernel: di_uninit_buf keep cur di_buf 6 (7 8 3)
Oct 30 11:34:13 vero4k kernel: codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
Oct 30 11:34:13 vero4k kernel: codec:vdec_create instance ffffff8006432000, total 1
Oct 30 11:34:13 vero4k kernel: codec:Video stbuf alloced at 0000000063b00000, size = 10485760
Oct 30 11:34:13 vero4k kernel: codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
Oct 30 11:34:13 vero4k kernel: codec:vdec_init set vfm decoder ffffff8006432000
Oct 30 11:34:13 vero4k kernel: codec:vdec_dev_reg.mem[0x64500000 -- 0x674fffff]
Oct 30 11:34:13 vero4k kernel: codec:H264 sysinfo: 1920x1080 duration=3840, pts_outside=1,
Oct 30 11:34:13 vero4k kernel: codec:vdec_request_irq ffffffc001699d78, vh264-irq
Oct 30 11:34:13 vero4k kernel: DI: di_receiver_event_fun: vframe provider reg
Oct 30 11:34:13 vero4k mediacenter[19766]: OPEN es DEVICE
Oct 30 11:34:13 vero4k mediacenter[19766]: [codec_reset:1146]ret=0
Oct 30 11:34:13 vero4k kernel: set run_early_proc_fun_flag to 1
Oct 30 11:34:13 vero4k kernel: codec:vdec_init, vf_provider_name =
Oct 30 11:34:13 vero4k kernel: codec:video first pts = 0
Oct 30 11:34:13 vero4k kernel: codec:vdec_request_irq ffffffc00168b1e8, parser
Oct 30 11:34:13 vero4k kernel: codec:video_blackout_policy_store(1)
Oct 30 11:34:13 vero4k kernel: codec:video first checkin pts = 88eaa3
Oct 30 11:34:13 vero4k kernel: codec:first check in vpts <0x2a:0x88eaa3> ok!
Oct 30 11:34:13 vero4k kernel: codec:Enter set parameter cmd1.
Oct 30 11:34:13 vero4k kernel: codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
Oct 30 11:34:13 vero4k kernel: codec:actual_dpb_size 15 max_dpb_size 3
Oct 30 11:34:13 vero4k kernel: codec:video first pts = 88eaa3
Oct 30 11:34:13 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback disable
Oct 30 11:34:13 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
Oct 30 11:34:13 vero4k kernel: i2s/958 same source - init spdif
Oct 30 11:34:13 vero4k kernel: aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1), stream format=1
Oct 30 11:34:13 vero4k kernel: aml_spdif_dai: set divider = 2 for i2s shared clock
Oct 30 11:34:13 vero4k kernel: aml_audio_hw: IEC958 PCM32
Oct 30 11:34:13 vero4k kernel: hdmitx: audio: aout notify rate 48000
Oct 30 11:34:13 vero4k kernel: hdmitx: audio: aout notify size 32
Oct 30 11:34:13 vero4k kernel: hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
Oct 30 11:34:13 vero4k kernel: hdmitx: audio: no update
Oct 30 11:34:14 vero4k kernel: pre_de_buf_config: source change: 0x0/0/0/0=>0x8009/1920/1080/0
Oct 30 11:34:14 vero4k kernel: vpts to scr, apts = 0x0, vpts = 0x88eaa3
Oct 30 11:34:14 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:88f8b3,
Oct 30 11:34:14 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: I2S playback enable
Oct 30 11:34:14 vero4k kernel: aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
Oct 30 11:34:14 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:15 vero4k kernel: DI: recycle_keep_buffer recycle keep cur di_buf 6 (
Oct 30 11:34:15 vero4k kernel: DI: 7
Oct 30 11:34:15 vero4k kernel: DI: 8
Oct 30 11:34:15 vero4k kernel: DI: 3
Oct 30 11:34:15 vero4k kernel: DI: )
Oct 30 11:34:15 vero4k kernel: vidioc_qbuf skip: index:771990:771989
Oct 30 11:34:15 vero4k kernel: codec:finished correct frame dur
Oct 30 11:34:15 vero4k kernel: codec: new=3840,old_duration=3840,cnt=25
Oct 30 11:34:16 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:16 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:8abab3,
Oct 30 11:34:16 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:17 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:8b6373,
Oct 30 11:34:17 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:17 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:19 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:8ddc43,
Oct 30 11:34:19 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:19 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:21 vero4k kernel: codec:fix_frame_rate mode play
Oct 30 11:34:22 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:925d63,
Oct 30 11:34:22 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:926b73,
Oct 30 11:34:22 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:32 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:32 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:a05f53,
Oct 30 11:34:32 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:38 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:38 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:a81013,
Oct 30 11:34:38 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:46 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:46 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:b3df83,
Oct 30 11:34:46 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:47 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:47 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:47 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:47 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:b54d23,
Oct 30 11:34:47 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:b55b33,
Oct 30 11:34:47 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:49 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:b74763,
Oct 30 11:34:49 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:49 vero4k kernel: codec:VsyncEnableVideoLayer
Oct 30 11:34:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
Oct 30 11:34:58 vero4k kernel: codec:[video4osd] first picture {1920,1080} pts:0,
FTR: I applied the October update this morning, and still the problem occurs.
I have just reproduced the issue again whilst watching dmesg and here are the entires you were after:
[11702.653307] codec:fix_frame_rate mode play
[11702.734731] codec: Frame parameters: Size 1920x1080
[11702.734768] codec: interlace-bottom
[11702.734788] codec: (Full type: 0x00008003)
[11702.734811] codec: Bit depth: 8-bit, Colour range: limited
[11702.734834] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11702.734850] codec: No master display info
[11702.735022] codec:[video4osd] first picture {1920,1080} pts:0,
[11702.754866] codec:[video4osd] first picture {1920,1080} pts:f77063,
[11702.774951] codec:VsyncEnableVideoLayer
[11731.394696] codec: Frame parameters: Size 1920x1080
[11731.394706] codec: interlace-top
[11731.394710] codec: (Full type: 0x00008009)
[11731.394716] codec: Bit depth: 8-bit, Colour range: limited
[11731.394720] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11731.394724] codec: No master display info
[11731.394781] codec:[video4osd] first picture {1920,1080} pts:11ec523,
[11731.414745] codec:[video4osd] first picture {1920,1080} pts:0,
[11731.434830] codec:VsyncEnableVideoLayer
[11731.754698] codec: Frame parameters: Size 1920x1080
[11731.754707] codec: interlace-top
[11731.754711] codec: (Full type: 0x00008009)
[11731.754716] codec: Bit depth: 8-bit, Colour range: limited
[11731.754721] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11731.754724] codec: No master display info
[11731.754786] codec:[video4osd] first picture {1920,1080} pts:11f43b3,
[11731.774742] codec:[video4osd] first picture {1920,1080} pts:0,
[11731.794825] codec:VsyncEnableVideoLayer
[11767.254723] codec: Frame parameters: Size 1920x1080
[11767.254759] codec: interlace-top
[11767.254780] codec: (Full type: 0x00008009)
[11767.254803] codec: Bit depth: 8-bit, Colour range: limited
[11767.254824] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11767.254841] codec: No master display info
[11767.255008] codec:[video4osd] first picture {1920,1080} pts:1500b33,
[11767.274875] codec:[video4osd] first picture {1920,1080} pts:0,
[11767.295056] codec:VsyncEnableVideoLayer
[11767.874720] codec: Frame parameters: Size 1920x1080
[11767.874755] codec: interlace-bottom
[11767.874776] codec: (Full type: 0x00008003)
[11767.874796] codec: Bit depth: 8-bit, Colour range: limited
[11767.874818] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11767.874835] codec: No master display info
[11767.875005] codec:[video4osd] first picture {1920,1080} pts:0,
[11767.894876] codec:[video4osd] first picture {1920,1080} pts:150ec33,
[11767.915066] codec:VsyncEnableVideoLayer
[11768.274723] codec: Frame parameters: Size 1920x1080
[11768.274759] codec: interlace-bottom
[11768.274779] codec: (Full type: 0x00008003)
[11768.274800] codec: Bit depth: 8-bit, Colour range: limited
[11768.274822] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11768.274840] codec: No master display info
[11768.275012] codec:[video4osd] first picture {1920,1080} pts:0,
[11768.294866] codec:[video4osd] first picture {1920,1080} pts:15178d3,
[11768.315074] codec:VsyncEnableVideoLayer
[11770.534695] codec: Frame parameters: Size 1920x1080
[11770.534706] codec: interlace-top
[11770.534710] codec: (Full type: 0x00008009)
[11770.534714] codec: Bit depth: 8-bit, Colour range: limited
[11770.534719] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11770.534722] codec: No master display info
[11770.534782] codec:[video4osd] first picture {1920,1080} pts:1548c53,
[11770.554747] codec:[video4osd] first picture {1920,1080} pts:0,
[11770.574822] codec:VsyncEnableVideoLayer
[11784.094724] codec: Frame parameters: Size 1920x1080
[11784.094758] codec: interlace-top
[11784.094778] codec: (Full type: 0x00008009)
[11784.094800] codec: Bit depth: 8-bit, Colour range: limited
[11784.094822] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11784.094839] codec: No master display info
[11784.095011] codec:[video4osd] first picture {1920,1080} pts:1672b83,
[11784.114878] codec:[video4osd] first picture {1920,1080} pts:0,
[11784.135107] codec:VsyncEnableVideoLayer
[11785.174771] codec:[video4osd] first picture {1920,1080} pts:0,
[11785.194745] codec:[video4osd] first picture {1920,1080} pts:168a733,
[11785.214826] codec:VsyncEnableVideoLayer
[11790.514733] codec:[video4osd] first picture {1920,1080} pts:0,
[11790.574743] codec:[video4osd] first picture {1920,1080} pts:0,
[11790.594821] codec:VsyncEnableVideoLayer
[11791.038988] codec:video_blackout_policy_store(0)
[11791.040959] [tsync_avevent]event:1, param 1
[11791.040973] video pause!
[11791.054336] DI: di_receiver_event_fun , is_bypass() 0 trick_mode 0 bypass_all 0
[11791.054345] di_receiver_event_fun: vf_notify_receiver unreg
[11791.054363] DI: di_unreg_process unreg start 1.
[11791.054373] codec:keep exit is di
[11791.054378] [tsync_avevent]event:2, param 0
[11791.054383] codec:video first pts = 0
[11791.054392] DI: di_unreg_process vf unreg cost 0 ms.
[11791.054395] DI: di_unreg_process unreg stop 0.
[11791.054408] di_uninit_buf keep cur di_buf 7 (0 2 7)
[11791.064433] codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
[11791.064691] codec:vdec_create instance ffffff8005878000, total 1
[11791.064737] codec:Video stbuf alloced at 0000000063b00000, size = 10485760
[11791.064749] codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
[11791.064753] codec:vdec_init set vfm decoder ffffff8005878000
[11791.064761] codec:vdec_dev_reg.mem[0x64500000 -- 0x674fffff]
[11791.065565] codec:H264 sysinfo: 1920x1080 duration=3840, pts_outside=1,
[11791.065934] codec:vdec_request_irq ffffffc001699df0, vh264-irq
[11791.065961] DI: di_receiver_event_fun: vframe provider reg
[11791.076181] set run_early_proc_fun_flag to 1
[11791.076363] codec:vdec_init, vf_provider_name =
[11791.077102] codec:video first pts = 0
[11791.077117] codec:vdec_request_irq ffffffc00168b260, parser
[11791.077890] codec:video_blackout_policy_store(1)
[11791.256390] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[11791.256408] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[11791.256492] i2s/958 same source - init spdif
[11791.256502] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1), stream format=1
[11791.256511] aml_spdif_dai: set divider = 2 for i2s shared clock
[11791.256521] aml_audio_hw: IEC958 PCM32
[11791.256530] hdmitx: audio: aout notify rate 48000
[11791.256534] hdmitx: audio: aout notify size 32
[11791.256539] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[11791.256543] hdmitx: audio: no update
[11791.269365] codec:video first checkin pts = 17395a3
[11791.269368] codec:first check in vpts <0x2a:0x17395a3> ok!
[11791.269499] codec:Enter set parameter cmd1.
[11791.269528] codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
[11791.269533] codec:actual_dpb_size 15 max_dpb_size 3
[11791.269592] codec:video first pts = 17395a3
[11791.484218] pre_de_buf_config: source change: 0x0/0/0/0=>0x8009/1920/1080/0
[11792.269714] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[11792.269719] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[11792.274717] vpts to scr, apts = 0x0, vpts = 0x17395a3
[11792.274751] codec:[video4osd] first picture {1920,1080} pts:173a3b3,
[11792.294781] codec:VsyncEnableVideoLayer
[11792.975725] DI: recycle_keep_buffer recycle keep cur di_buf 7 (
[11792.975736] DI: 0
[11792.975742] DI: 2
[11792.975744] DI: 7
[11792.975747] DI: )
[11793.391708] codec:finished correct frame dur
[11793.391721] codec: new=3840,old_duration=3840,cnt=25
[11798.834694] codec: Frame parameters: Size 1920x1080
[11798.834704] codec: interlace-top
[11798.834708] codec: (Full type: 0x00008009)
[11798.834713] codec: Bit depth: 8-bit, Colour range: limited
[11798.834718] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11798.834722] codec: No master display info
[11798.834778] codec:[video4osd] first picture {1920,1080} pts:17bb6e3,
[11798.854746] codec:[video4osd] first picture {1920,1080} pts:0,
[11798.874821] codec:VsyncEnableVideoLayer
[11799.334696] codec: Frame parameters: Size 1920x1080
[11799.334706] codec: interlace-bottom
[11799.334711] codec: (Full type: 0x00008003)
[11799.334716] codec: Bit depth: 8-bit, Colour range: limited
[11799.334720] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11799.334723] codec: No master display info
[11799.334780] codec:[video4osd] first picture {1920,1080} pts:0,
[11799.354750] codec:[video4osd] first picture {1920,1080} pts:17c6db3,
[11799.374817] codec:VsyncEnableVideoLayer
[11799.954697] codec: Frame parameters: Size 1920x1080
[11799.954707] codec: interlace-top
[11799.954712] codec: (Full type: 0x00008009)
[11799.954717] codec: Bit depth: 8-bit, Colour range: limited
[11799.954721] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11799.954725] codec: No master display info
[11799.954786] codec:[video4osd] first picture {1920,1080} pts:17d40a3,
[11799.974743] codec:[video4osd] first picture {1920,1080} pts:0,
[11799.994824] codec:VsyncEnableVideoLayer
[11801.214695] codec: Frame parameters: Size 1920x1080
[11801.214707] codec: interlace-top
[11801.214711] codec: (Full type: 0x00008009)
[11801.214716] codec: Bit depth: 8-bit, Colour range: limited
[11801.214721] codec: Primaries: bt709, Transfer function: bt709, RGB-YCC: bt709
[11801.214724] codec: No master display info
[11801.214779] codec:[video4osd] first picture {1920,1080} pts:17eca63,
[11801.234747] codec:[video4osd] first picture {1920,1080} pts:0,
[11801.254816] codec:VsyncEnableVideoLayer
The stutter occurred around this time:
[11791.038988] codec:video_blackout_policy_store(0)
[11791.040959] [tsync_avevent]event:1, param 1
[11791.040973] video pause!
Thanks. Didn’t make any changes that would change this behaviour.
I’ll produce a new kernel with new symbols shortly.
Thanks Sam, happy to reproduce and provide more logs once the new kernel is ready.
Today I’ve been repeating my tests against an SD MPEG2 channel stream, and interestingly that was not affected. As mentioned before, I have H/W acceleration enabled for all codecs, and I could see it was using H/W acceleration for the SD MPEG2 stream.
My test case for reproducing the issue is to play ITV HD, which uses the h264 codec. As mentioned, recordings on HD channels, (including ITV HD) are fine, it’s just LiveTV.
In the meantime, I’ve sadly reverted back to my 10yr old HTPC for daily use, where these same streams play fine with no stuttering. That’s a Revo 3700 machine with NVidia ION2 (VDPAU) incase your interested.
That was a very difficult decision to make, but with this issue dragging along I had no choice, since my vero has so far failed the WAT (Wife Acceptance Testing) 
I’ve now got both boxes hooked up to my TV in different HDMI ports so I can continue working with you on testing new builds etc. I hope one day to move back to the Vero4K for daily use.
We should be able to get this resolved promptly for you.
Thanks for your patience
Sam
Any news?
Hi — sorry, I was focusing on the October update the past couple of days. I’ll get a new kernel built today.
No problems, I saw the various posts relating to the October update so had assumed you were embroiled in those issues.
Is the new kernel intended to fix the issue, or provide extra logging to help you debug the issue further?
If the latter, then once the kernel is built, I’ll just need to know which logs you need:
- grab-logs -A
- dropwatch capture
- dmesg output
- all of the above?
Just to get us looking in the right direction for now
Sam
I’ve been thinking about this – and I’m not certain that the Live TV issue you are experiencing is caused by a packet drop. But that’s still something worth exploring and we should eliminate this drop if possible.
Built top of tree: GitHub - osmc/vero3-linux (master branch).
I’ve uploaded a new kernel here: https://collab.osmc.tv/s/nf6i27tyLPjTSU1
I’ve also uploaded vmlinux there as well. Using addr2line we can then pinpoint what’s causing these drops.
Note that you need the aarch64 version of addr2line to do this; so you could run sudo apt-get install aarch64-toolchain-osmc and chroot /opt/osmc/aarch64-toolchain-osmc to run addr2line. Or you can just give me the offsets again and I can check it.
Cheers
Sam