piwall video profiling experiments

video profiling 

    See these results in a spreadsheet: https://docs.google.com/spreadsheets/d/1vP3O_LLLR4p_q1lOpIfwUwL1d7bTHbV2OFuT1eG205Q/edit#gid=0

    how to:
        mbuffer high water mark:

            dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected],[email protected] "cat /tmp/mbuffer.out | awk '{ print \$14; }' | sort -n | tail -2" 2>/dev/null

        socket receive buffer high water mark:

            while sleep 1 ; do date -u ; dsh -r ssh -c -F10 --remoteshellopt '-o LogLevel=ERROR' -M -m [email protected],[email protected],[email protected],[email protected] "netstat --udp -an | grep '239.0.1.23:1234'" | sort | grep -v 'udp        0' ; echo "" ; done

        udp packet loss:

            while sleep 1 ; do date -u ; dsh -r ssh -c -F10 --remoteshellopt '-o LogLevel=ERROR' -M -m [email protected],[email protected],[email protected],[email protected] "netstat -anus | grep receive | grep errors" | sort | grep -v -E ' 0 .* errors'; echo "" ; done

        omxplayer pauses:

            dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Pause'" 2>/dev/null

        omxplayer pause close calls:

            if the 'V:N.NN' gets below 0.1, omxplayer will pause ( https://github.com/popcornmix/omxplayer/blob/1f1d0ccd65d3a1caa86dc79d2863a8f067c8e3f8/omxplayer.cpp#L1648 )

            adjust the `grep -v` filters below to align with the video's start and end times, where we expect the video buffers to be low

            dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '02:26:' | grep -v '04:37:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort

            use `--key 10` to sort by audio rather than video

    maru vs trap: 
        ./broadcast --url https://www.youtube.com/watch\?v\=6wVZK0W0SAo # maru vs trap gsl

        trial 1 (mpegts 5s threshold)
            mbuffer high water mark: 0%
            omxplayer pauses: none
            socket receive buffer high water mark: 207296
            udp packet loss: 0

            omxplayer pause close calls: (~1h 31m after video start)

        [email protected]: 03:57:27 T:18446744071720912397   DEBUG: Normal M:5480045509 (A:5481299600 V:5481320078) P:0 A:1.25 V:1.27
        [email protected]: 03:57:27 T:18446744071720909691   DEBUG: Normal M:5480064495 (A:5481299600 V:5481320078) P:0 A:1.24 V:1.26
        [email protected]: 03:58:34 T:18446744071786968793   DEBUG: Normal M:5546067017 (A:5547337144 V:5547369400) P:0 A:1.27 V:1.30
        [email protected]: 03:57:27 T:18446744071720902602   DEBUG: Normal M:5480021260 (A:5481299600 V:5481320078) P:0 A:1.28 V:1.30

        trial 2 (mpegts 5s threshold)
            mbuffer high water mark: 0%
            omxplayer pauses: none
            socket receive buffer high water mark: 257152
            udp packet loss: 0

            omxplayer pause close calls: (~1h 31m after video start)

        [email protected]: 07:27:36 T:2030230323   DEBUG: Normal M:5480058951 (A:5481299600 V:5481320078) P:0 A:1.24 V:1.26
        [email protected]: 07:29:33 T:2147089989   DEBUG: Normal M:5596944794 (A:5598119189 V:5598186833) P:0 A:1.17 V:1.24
        [email protected]: 07:27:36 T:2030226652   DEBUG: Normal M:5480017480 (A:5481299600 V:5481320078) P:0 A:1.28 V:1.30
        [email protected]: 07:27:36 T:2030224358   DEBUG: Normal M:5480029901 (A:5481299600 V:5481320078) P:0 A:1.27 V:1.29

        trial 3 (with ismv, aac audio, 2 second fragment size)
            mbuffer high water mark: 1% (100% on piwall3)
            omxplayer pauses: [email protected]: 05:15:29 T:18446744073108888524   DEBUG: Pause 4.16,-0.56 (0,1,0,0) 10.00
            socket receive buffer high water mark: 393600, 3358720 (excluding piwall3)
            udp packet loss: 0 (except on piwall3)

            omxplayer pause close calls (06:07 is 1h 31m after video start):

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '04:36:' | grep -v '06:48:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 05:40:53 T:922845027   DEBUG: Normal M:3855677542 (A:3855836009 V:3855858537) P:0 A:0.16 V:0.18
[email protected]: 06:55:22 T:1097216742   DEBUG: Normal M:5813645744 (A:2350788209 V:2338309170) P:0 A:-3462.86 V:-3475.34
[email protected]: 05:40:53 T:922867723   DEBUG: Normal M:3855649765 (A:3855836009 V:3855858537) P:0 A:0.19 V:0.21
[email protected]: 05:40:53 T:922864934   DEBUG: Normal M:3855657165 (A:3855836009 V:3855858537) P:0 A:0.18 V:0.20

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '04:36:' | grep -v '06:48:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 06:07:56 T:18446744071961071804   DEBUG: Normal M:5479335255 (A:5479444898 V:5481449170) P:0 A:0.11 V:2.11
[email protected]: 06:55:22 T:1097190982   DEBUG: Normal M:5813620918 (A:2350323810 V:2338309170) P:0 A:-3463.30 V:-3475.31
[email protected]: 06:07:56 T:18446744071961094577   DEBUG: Normal M:5479293120 (A:5479444898 V:5481449170) P:0 A:0.15 V:2.16
[email protected]: 06:07:56 T:18446744071961093443   DEBUG: Normal M:5479306482 (A:5479444898 V:5481449170) P:0 A:0.14 V:2.14


        trial 4 (with ismv, mp2 audio, 200 ms fragment size)
            mbuffer high water mark: 1% (100% on piwall3)
            omxplayer pauses: [email protected]: 16:00:58 T:18446744073182738488   DEBUG: Pause 5.72,0.08 (0,1,1,0) 10.00
            socket receive buffer high water mark: 112832 (excluding piwall3)
            udp packet loss: 0 (except on piwall3)

            omxplayer pause close calls (these are not near 1h 31m mark):

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '15:45:' | grep -v '17:57:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 16:50:26 T:18446744071856548892   DEBUG: Normal M:3864921851 (A:3865631899 V:3865845317) P:0 A:0.71 V:0.92
[email protected]: 18:23:03 T:18446744073118602179   DEBUG: Normal M:3136084803 (A:922885776 V:905738167) P:0 A:-2213.20 V:-2230.35
[email protected]: 16:50:26 T:18446744071856553563   DEBUG: Normal M:3864901379 (A:3865631899 V:3865845317) P:0 A:0.73 V:0.94
[email protected]: 16:50:26 T:18446744071856546691   DEBUG: Normal M:3864910729 (A:3865631899 V:3865845317) P:0 A:0.72 V:0.93
[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '15:45:' | grep -v '17:57:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 17:19:04 T:18446744073573649093   DEBUG: Normal M:5582051493 (A:5582738838 V:5582977400) P:0 A:0.69 V:0.93
[email protected]: 18:23:23 T:18446744073138145216   DEBUG: Normal M:3155628188 (A:922885776 V:905688117) P:0 A:-2232.74 V:-2249.94
[email protected]: 16:50:26 T:18446744071856553563   DEBUG: Normal M:3864901379 (A:3865631899 V:3865845317) P:0 A:0.73 V:0.94
[email protected]: 17:19:04 T:18446744073573650540   DEBUG: Normal M:5582024399 (A:5582738838 V:5582977400) P:0 A:0.71 V:0.95

        trial 5 (mpegts 5s threshold)
            mbuffer high water mark: 1% (34% on piwall3)
            omxplayer pauses: [email protected]: 20:41:11 T:18446744072815942116   DEBUG: Pause 5.50,-0.30 (0,1,1,0) 10.00
            socket receive buffer high water mark: 144320
            udp packet loss: 0 (except on piwall3)

            omxplayer pause close calls (20:04 is 1h 31m after video start):

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '18:33:' | grep -v '20:44:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 20:04:31 T:1201631515   DEBUG: Normal M:5480057108 (A:5481299600 V:5481320078) P:0 A:1.24 V:1.26
[email protected]: 21:22:02 T:1557801403   DEBUG: Normal M:8819615780 (A:7747160822 V:7682252144) P:0 A:-1072.45 V:-1137.36
[email protected]: 20:04:31 T:1201623327   DEBUG: Normal M:5480009908 (A:5481299600 V:5481320078) P:0 A:1.29 V:1.31
[email protected]: 20:04:31 T:1201625407   DEBUG: Normal M:5480021691 (A:5481299600 V:5481320078) P:0 A:1.28 V:1.30
[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '18:33:' | grep -v '20:44:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 20:06:28 T:1318492122   DEBUG: Normal M:5596919605 (A:5598119189 V:5598186833) P:0 A:1.20 V:1.27
[email protected]: 21:22:02 T:1557759700   DEBUG: Normal M:8819574077 (A:7747056333 V:7682235466) P:0 A:-1072.52 V:-1137.34
[email protected]: 20:06:28 T:1318487698   DEBUG: Normal M:5596875062 (A:5598119189 V:5598186833) P:0 A:1.24 V:1.31
[email protected]: 20:06:28 T:1318490423   DEBUG: Normal M:5596887664 (A:5598119189 V:5598186833) P:0 A:1.23 V:1.30

        trial 6 (with ismv, mp2 audio, 200 ms fragment size, cable swapped)
            mbuffer high water mark: 1% (100% on piwall3)
            omxplayer pauses: [email protected]: [email protected]: 05:35:47 T:1117791933   DEBUG: Pause 4.96,-0.02 (0,1,0,0) 10.00
            socket receive buffer high water mark: 348992 (excluding piwall3)
            udp packet loss: 0 (except on piwall3)

            omxplayer pause close calls (these are not exactly at the 1h 31m mark):

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '05:26:' | grep -v '07:38:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 06:31:15 T:150776863   DEBUG: Normal M:3864919178 (A:3865631899 V:3865845317) P:0 A:0.71 V:0.93
[email protected]: 10:04:51 T:82227506   DEBUG: Normal M:1323510238 (A:599176388 V:554954400) P:0 A:-724.33 V:-768.56
[email protected]: 06:31:15 T:150720096   DEBUG: Normal M:3864883157 (A:3865631899 V:3865845317) P:0 A:0.75 V:0.96
[email protected]: 06:31:15 T:150734468   DEBUG: Normal M:3864893997 (A:3865631899 V:3865845317) P:0 A:0.74 V:0.95
[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '05:26:' | grep -v '07:38:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 06:59:52 T:1867875576   DEBUG: Normal M:5582050932 (A:5582738838 V:5582977400) P:0 A:0.69 V:0.93
[email protected]: 10:04:51 T:82247686   DEBUG: Normal M:1323530417 (A:599176388 V:554987767) P:0 A:-724.35 V:-768.54
[email protected]: 06:59:52 T:1867833729   DEBUG: Normal M:5582009988 (A:5582738838 V:5582977400) P:0 A:0.73 V:0.97
[email protected]: 06:59:52 T:1867850194   DEBUG: Normal M:5582025950 (A:5582738838 V:5582977400) P:0 A:0.71 V:0.95

        trial 7 (with ismv, mp2 audio, 200 ms fragment size, piwall3 cable swapped, piwall3 switch port swapped with piwall2)

            piwall3 still freezes!

        trial 8 (with ismv, mp2 audio, 200 ms fragment size, piwall3 cable swapped, piwall3 switch port swapped with piwall2, piwall3 and piwall2 SD cards swapped)

            top right screen (same hardware!) still freezes!

        trial 9 (with ismv, mp2 audio, 200 ms fragment size, piwall3 cable swapped, piwall3 switch port swapped with piwall2, piwall3 and piwall2 SD cards swapped, piwall3 and 2 power cables and TV out cables swapped)  
            
            Sure enough, the same hardware freezes (top left screen).

        trial 10 (with ismv, mp2 audio, 200 ms fragment size, new piwall3 hardware)
            mbuffer high water mark: 1%
            omxplayer pauses: none
            socket receive buffer high water mark: 414592
            udp packet loss: 0

            omxplayer pause close calls (1h 34m):
[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '00:11:' | grep -vE '02:2[234]:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 01:44:18 T:614486831   DEBUG: Normal M:5582045856 (A:5582738838 V:5582977400) P:0 A:0.69 V:0.93
[email protected]: 01:15:41 T:18446744072606934443   DEBUG: Normal M:3864892899 (A:3865631899 V:3865845317) P:0 A:0.74 V:0.95
[email protected]: 01:15:41 T:18446744072606991083   DEBUG: Normal M:3864875654 (A:3865631899 V:3865845317) P:0 A:0.76 V:0.97
[email protected]: 01:15:41 T:18446744072606921733   DEBUG: Normal M:3864891719 (A:3865631899 V:3865845317) P:0 A:0.74 V:0.95

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '00:11:' | grep -vE '02:2[234]:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 01:44:18 T:614486831   DEBUG: Normal M:5582045856 (A:5582738838 V:5582977400) P:0 A:0.69 V:0.93
[email protected]: 01:44:18 T:614500277   DEBUG: Normal M:5582030969 (A:5582738838 V:5582977400) P:0 A:0.71 V:0.95
[email protected]: 01:44:18 T:614485815   DEBUG: Normal M:5582005454 (A:5582738838 V:5582977400) P:0 A:0.73 V:0.97
[email protected]: 01:44:18 T:614505604   DEBUG: Normal M:5582017211 (A:5582738838 V:5582977400) P:0 A:0.72 V:0.96

        trial 11 (mpegts 5s threshold)
            mbuffer high water mark: 0%
            omxplayer pauses: none
            socket receive buffer high water mark: 183680
            udp packet loss: 0

            omxplayer pause close calls: (~1h 31m after video start)

[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '05:53:' | grep -v '08:04:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 11 | head -1" 2>/dev/null | sort
[email protected]: 07:24:33 T:18446744073264380076   DEBUG: Normal M:5480066760 (A:5481299600 V:5481320078) P:0 A:1.23 V:1.25
[email protected]: 07:25:39 T:18446744073330445597   DEBUG: Normal M:5546117358 (A:5547337144 V:5547369400) P:0 A:1.22 V:1.25
[email protected]: 07:24:33 T:18446744073264383655   DEBUG: Normal M:5480025806 (A:5481299600 V:5481320078) P:0 A:1.27 V:1.29
[email protected]: 07:24:33 T:18446744073264383500   DEBUG: Normal M:5480038026 (A:5481299600 V:5481320078) P:0 A:1.26 V:1.28
[laptop] ~ % dsh -r ssh -c -M -m [email protected],[email protected],[email protected],[email protected] "cat omxplayer.log | grep -i 'DEBUG: Normal' | grep -v '05:53:' | grep -v '08:04:' | cut -d'/' -f1 | sort --numeric-sort --field-separator=':' --key 10 | head -1" 2>/dev/null | sort
[email protected]: 07:26:30 T:18446744073381252072   DEBUG: Normal M:5596940074 (A:5598119189 V:5598186833) P:0 A:1.18 V:1.25
[email protected]: 07:26:30 T:18446744073381254913   DEBUG: Normal M:5596927264 (A:5598119189 V:5598186833) P:0 A:1.19 V:1.26
[email protected]: 07:26:30 T:18446744073381258241   DEBUG: Normal M:5596900999 (A:5598119189 V:5598186833) P:0 A:1.22 V:1.29
[email protected]: 07:26:30 T:18446744073381256823   DEBUG: Normal M:5596911819 (A:5598119189 V:5598186833) P:0 A:1.21 V:1.28