Mir

Bug #1532202
Comment #11

Comment 11 for bug 1532202

Revision history for this message

Alan Griffiths (alan-griffiths) wrote on 2016-01-12:

#11

The nested server sees a big increase in "render time" (from 1.5-2.5ms to 22.25ms for output #1) it also appears to be rendering to output #2 at a similar rate despite there being no updates visible on that output.

22.25ms is slow enough to be causing problems.

$ MIR_CLIENT_PERF_REPORT=log mir_demo_server --host host --display-config sidebyside&
$ MIR_CLIENT_PERF_REPORT=log mir_demo_client_egltriangle

[1452607758.598397] perf: mir_demo_client_egltriangle: 63.61 FPS, render time 1.58ms, buffer lag 46.22ms (3 buffers)
[1452607758.617656] perf: Mir nested display for output #1: 62.43 FPS, render time 4.52ms, buffer lag 44.11ms (3 buffers)
[1452607759.599679] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 1.49ms, buffer lag 48.59ms (3 buffers)
[1452607759.619060] perf: Mir nested display for output #1: 59.94 FPS, render time 4.27ms, buffer lag 45.78ms (3 buffers)
[1452607760.600595] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.71ms, buffer lag 48.28ms (3 buffers)
[1452607760.619975] perf: Mir nested display for output #1: 60.00 FPS, render time 4.38ms, buffer lag 45.66ms (3 buffers)
[1452607761.604715] perf: mir_demo_client_egltriangle: 59.76 FPS, render time 2.66ms, buffer lag 47.52ms (3 buffers)
[1452607761.621990] perf: Mir nested display for output #1: 59.94 FPS, render time 5.29ms, buffer lag 44.77ms (3 buffers)
[1452607762.605814] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 2.59ms, buffer lag 47.42ms (3 buffers)
[1452607762.624675] perf: Mir nested display for output #1: 59.88 FPS, render time 5.57ms, buffer lag 44.52ms (3 buffers)
[1452607763.623363] perf: mir_demo_client_egltriangle: 59.98 FPS, render time 2.08ms, buffer lag 47.95ms (3 buffers)
[1452607763.640729] perf: Mir nested display for output #1: 60.03 FPS, render time 5.37ms, buffer lag 44.65ms (3 buffers)
[1452607764.639478] perf: mir_demo_client_egltriangle: 60.03 FPS, render time 2.33ms, buffer lag 47.68ms (3 buffers)
[1452607764.641645] perf: Mir nested display for output #1: 60.00 FPS, render time 5.36ms, buffer lag 44.73ms (3 buffers)
[1452607765.640454] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.95ms, buffer lag 48.09ms (3 buffers)
[1452607765.644453] perf: Mir nested display for output #1: 59.88 FPS, render time 5.36ms, buffer lag 44.69ms (3 buffers)
[1452607766.658126] perf: mir_demo_client_egltriangle: 59.98 FPS, render time 1.92ms, buffer lag 48.15ms (3 buffers)
[1452607766.659530] perf: Mir nested display for output #1: 60.09 FPS, render time 5.28ms, buffer lag 44.69ms (3 buffers)
[1452607767.669327] perf: mir_demo_client_egltriangle: 59.34 FPS, render time 2.15ms, buffer lag 48.15ms (3 buffers)
[1452607767.675766] perf: Mir nested display for output #1: 59.05 FPS, render time 5.37ms, buffer lag 45.19ms (3 buffers)
[1452607768.676957] perf: mir_demo_client_egltriangle: 60.57 FPS, render time 1.53ms, buffer lag 48.18ms (3 buffers)
[1452607768.678330] perf: Mir nested display for output #1: 60.87 FPS, render time 4.59ms, buffer lag 44.94ms (3 buffers)
[1452607769.677109] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.61ms, buffer lag 48.47ms (3 buffers)
[1452607769.679337] perf: Mir nested display for output #1: 59.94 FPS, render time 4.39ms, buffer lag 45.65ms (3 buffers)
[1452607769.972669] mirserver: New display configuration:
[1452607769.976514] mirserver: 0.1: LVDS 4.7" 61x102mm
[1452607769.976606] mirserver: Current mode 768x1280 60.00Hz
[1452607769.976697] mirserver: Preferred mode 768x1280 60.00Hz
[1452607769.976758] mirserver: Logical position +0+0
[1452607769.980665] mirserver: 0.2: DisplayPort 0.0" 0x0mm
[1452607769.980818] mirserver: Current mode 1920x1080 60.00Hz
[1452607769.980909] mirserver: Preferred mode 1920x1080 60.00Hz
[1452607769.981001] mirserver: Logical position +768+0
Surface occluded
Surface exposed
[1452607770.693224] perf: Mir nested display for output #1: 41.46 FPS, render time 18.52ms, buffer lag 53.29ms (3 buffers)
[1452607770.696795] perf: mir_demo_client_egltriangle: 44.16 FPS, render time 4.61ms, buffer lag 62.96ms (3 buffers)
[1452607771.091362] mirserver: New display configuration:
[1452607771.100274] mirserver: 0.1: LVDS 4.7" 61x102mm
[1452607771.100427] mirserver: Current mode 768x1280 60.00Hz
[1452607771.100518] mirserver: Preferred mode 768x1280 60.00Hz
[1452607771.100610] mirserver: Logical position +0+0
[1452607771.100702] mirserver: 0.2: unused DisplayPort
[1452607771.100885] perf: Mir nested display for output #2: 41.21 FPS, render time 388727.51ms, buffer lag 45.55ms (3 buffers)
Surface occluded
Surface exposed
[1452607771.699878] perf: Mir nested display for output #1: 55.66 FPS, render time 11.02ms, buffer lag 43.35ms (3 buffers)
[1452607771.712940] perf: mir_demo_client_egltriangle: 56.10 FPS, render time 3.53ms, buffer lag 50.23ms (3 buffers)
[1452607772.714375] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 1.56ms, buffer lag 48.44ms (3 buffers)
[1452607772.715748] perf: Mir nested display for output #1: 60.09 FPS, render time 4.71ms, buffer lag 45.24ms (3 buffers)
[1452607773.469296] mirserver: New display configuration:
[1452607773.472745] mirserver: 0.1: LVDS 4.7" 61x102mm
[1452607773.472867] mirserver: Current mode 768x1280 60.00Hz
[1452607773.472959] mirserver: Preferred mode 768x1280 60.00Hz
[1452607773.473050] mirserver: Logical position +0+0
[1452607773.481169] mirserver: 0.2: DisplayPort 0.0" 0x0mm
[1452607773.484465] mirserver: Current mode 1920x1080 60.00Hz
[1452607773.484678] mirserver: Preferred mode 1920x1080 60.00Hz
[1452607773.484861] mirserver: Logical position +768+0
Surface occluded
Surface exposed
[1452607773.721761] perf: mir_demo_client_egltriangle: 52.63 FPS, render time 1.96ms, buffer lag 54.26ms (3 buffers)
[1452607773.723226] perf: Mir nested display for output #1: 51.63 FPS, render time 9.35ms, buffer lag 49.04ms (3 buffers)
[1452607774.616099] perf: Mir nested display for output #2: 38.42 FPS, render time 418720.76ms, buffer lag 48.37ms (3 buffers)
[1452607774.721913] perf: mir_demo_client_egltriangle: 42.00 FPS, render time 8.06ms, buffer lag 63.71ms (3 buffers)
[1452607774.742789] perf: Mir nested display for output #1: 41.21 FPS, render time 23.11ms, buffer lag 48.90ms (3 buffers)
[1452607775.621654] perf: Mir nested display for output #2: 37.81 FPS, render time 25.47ms, buffer lag 53.59ms (3 buffers)
[1452607775.744651] perf: Mir nested display for output #1: 40.95 FPS, render time 23.05ms, buffer lag 49.83ms (3 buffers)
[1452607775.747733] perf: mir_demo_client_egltriangle: 40.97 FPS, render time 8.42ms, buffer lag 64.58ms (3 buffers)
[1452607776.664474] perf: Mir nested display for output #2: 37.42 FPS, render time 26.29ms, buffer lag 52.78ms (3 buffers)
[1452607776.745048] perf: Mir nested display for output #1: 42.00 FPS, render time 22.35ms, buffer lag 49.15ms (3 buffers)
[1452607776.765832] perf: mir_demo_client_egltriangle: 42.23 FPS, render time 7.41ms, buffer lag 64.04ms (3 buffers)
[1452607777.675553] perf: Mir nested display for output #2: 39.56 FPS, render time 24.56ms, buffer lag 52.31ms (3 buffers)
[1452607777.745139] perf: Mir nested display for output #1: 39.00 FPS, render time 24.83ms, buffer lag 53.03ms (3 buffers)
[1452607777.777125] perf: mir_demo_client_egltriangle: 38.57 FPS, render time 9.35ms, buffer lag 68.07ms (3 buffers)
[1452607778.696642] perf: Mir nested display for output #2: 38.19 FPS, render time 25.50ms, buffer lag 53.28ms (3 buffers)
[1452607778.778803] perf: Mir nested display for output #1: 39.69 FPS, render time 24.35ms, buffer lag 50.34ms (3 buffers)
[1452607778.794247] perf: mir_demo_client_egltriangle: 40.31 FPS, render time 9.20ms, buffer lag 65.19ms (3 buffers)
[1452607779.701983] perf: Mir nested display for output #2: 38.80 FPS, render time 23.95ms, buffer lag 54.05ms (3 buffers)
[1452607779.781367] perf: Mir nested display for output #1: 38.92 FPS, render time 25.09ms, buffer lag 52.36ms (3 buffers)
[1452607779.796261] perf: mir_demo_client_egltriangle: 38.96 FPS, render time 8.38ms, buffer lag 68.82ms (3 buffers)
[1452607780.716328] perf: Mir nested display for output #2: 38.46 FPS, render time 23.72ms, buffer lag 53.51ms (3 buffers)
[1452607780.796444] perf: Mir nested display for output #1: 39.40 FPS, render time 24.50ms, buffer lag 51.37ms (3 buffers)
[1452607780.829772] perf: mir_demo_client_egltriangle: 38.72 FPS, render time 8.66ms, buffer lag 68.50ms (3 buffers)
[1452607781.723042] perf: Mir nested display for output #2: 39.76 FPS, render time 24.06ms, buffer lag 51.54ms (3 buffers)
[1452607781.801816] perf: Mir nested display for output #1: 42.78 FPS, render time 22.50ms, buffer lag 47.75ms (3 buffers)
[1452607781.853029] perf: mir_demo_client_egltriangle: 43.01 FPS, render time 8.07ms, buffer lag 62.29ms (3 buffers)

22.25ms is slow enough to be causing problems.

$ MIR_CLIENT_PERF_REPORT=log mir_demo_server --host host --display-config sidebyside&
$ MIR_CLIENT_PERF_REPORT=log mir_demo_client_egltriangle

[1452607758.598397] perf: mir_demo_client_egltriangle: 63.61 FPS, render time 1.58ms, buffer lag 46.22ms (3 buffers)
[1452607758.617656] perf: Mir nested display for output #1: 62.43 FPS, render time 4.52ms, buffer lag 44.11ms (3 buffers)
[1452607759.599679] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 1.49ms, buffer lag 48.59ms (3 buffers)
[1452607759.619060] perf: Mir nested display for output #1: 59.94 FPS, render time 4.27ms, buffer lag 45.78ms (3 buffers)
[1452607760.600595] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.71ms, buffer lag 48.28ms (3 buffers)
[1452607760.619975] perf: Mir nested display for output #1: 60.00 FPS, render time 4.38ms, buffer lag 45.66ms (3 buffers)
[1452607761.604715] perf: mir_demo_client_egltriangle: 59.76 FPS, render time 2.66ms, buffer lag 47.52ms (3 buffers)
[1452607761.621990] perf: Mir nested display for output #1: 59.94 FPS, render time 5.29ms, buffer lag 44.77ms (3 buffers)
[1452607762.605814] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 2.59ms, buffer lag 47.42ms (3 buffers)
[1452607762.624675] perf: Mir nested display for output #1: 59.88 FPS, render time 5.57ms, buffer lag 44.52ms (3 buffers)
[1452607763.623363] perf: mir_demo_client_egltriangle: 59.98 FPS, render time 2.08ms, buffer lag 47.95ms (3 buffers)
[1452607763.640729] perf: Mir nested display for output #1: 60.03 FPS, render time 5.37ms, buffer lag 44.65ms (3 buffers)
[1452607764.639478] perf: mir_demo_client_egltriangle: 60.03 FPS, render time 2.33ms, buffer lag 47.68ms (3 buffers)
[1452607764.641645] perf: Mir nested display for output #1: 60.00 FPS, render time 5.36ms, buffer lag 44.73ms (3 buffers)
[1452607765.640454] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.95ms, buffer lag 48.09ms (3 buffers)
[1452607765.644453] perf: Mir nested display for output #1: 59.88 FPS, render time 5.36ms, buffer lag 44.69ms (3 buffers)
[1452607766.658126] perf: mir_demo_client_egltriangle: 59.98 FPS, render time 1.92ms, buffer lag 48.15ms (3 buffers)
[1452607766.659530] perf: Mir nested display for output #1: 60.09 FPS, render time 5.28ms, buffer lag 44.69ms (3 buffers)
[1452607767.669327] perf: mir_demo_client_egltriangle: 59.34 FPS, render time 2.15ms, buffer lag 48.15ms (3 buffers)
[1452607767.675766] perf: Mir nested display for output #1: 59.05 FPS, render time 5.37ms, buffer lag 45.19ms (3 buffers)
[1452607768.676957] perf: mir_demo_client_egltriangle: 60.57 FPS, render time 1.53ms, buffer lag 48.18ms (3 buffers)
[1452607768.678330] perf: Mir nested display for output #1: 60.87 FPS, render time 4.59ms, buffer lag 44.94ms (3 buffers)
[1452607769.677109] perf: mir_demo_client_egltriangle: 60.00 FPS, render time 1.61ms, buffer lag 48.47ms (3 buffers)
[1452607769.679337] perf: Mir nested display for output #1: 59.94 FPS, render time 4.39ms, buffer lag 45.65ms (3 buffers)
[1452607769.972669] mirserver: New display configuration:
[1452607769.976514] mirserver:   0.1: LVDS 4.7" 61x102mm
[1452607769.976606] mirserver:        Current mode 768x1280 60.00Hz
[1452607769.976697] mirserver:        Preferred mode 768x1280 60.00Hz
[1452607769.976758] mirserver:        Logical position +0+0
[1452607769.980665] mirserver:   0.2: DisplayPort 0.0" 0x0mm
[1452607769.980818] mirserver:        Current mode 1920x1080 60.00Hz
[1452607769.980909] mirserver:        Preferred mode 1920x1080 60.00Hz
[1452607769.981001] mirserver:        Logical position +768+0
Surface occluded
Surface exposed
[1452607770.693224] perf: Mir nested display for output #1: 41.46 FPS, render time 18.52ms, buffer lag 53.29ms (3 buffers)
[1452607770.696795] perf: mir_demo_client_egltriangle: 44.16 FPS, render time 4.61ms, buffer lag 62.96ms (3 buffers)
[1452607771.091362] mirserver: New display configuration:
[1452607771.100274] mirserver:   0.1: LVDS 4.7" 61x102mm
[1452607771.100427] mirserver:        Current mode 768x1280 60.00Hz
[1452607771.100518] mirserver:        Preferred mode 768x1280 60.00Hz
[1452607771.100610] mirserver:        Logical position +0+0
[1452607771.100702] mirserver:   0.2: unused DisplayPort
[1452607771.100885] perf: Mir nested display for output #2: 41.21 FPS, render time 388727.51ms, buffer lag 45.55ms (3 buffers)
Surface occluded
Surface exposed
[1452607771.699878] perf: Mir nested display for output #1: 55.66 FPS, render time 11.02ms, buffer lag 43.35ms (3 buffers)
[1452607771.712940] perf: mir_demo_client_egltriangle: 56.10 FPS, render time 3.53ms, buffer lag 50.23ms (3 buffers)
[1452607772.714375] perf: mir_demo_client_egltriangle: 59.94 FPS, render time 1.56ms, buffer lag 48.44ms (3 buffers)
[1452607772.715748] perf: Mir nested display for output #1: 60.09 FPS, render time 4.71ms, buffer lag 45.24ms (3 buffers)
[1452607773.469296] mirserver: New display configuration:
[1452607773.472745] mirserver:   0.1: LVDS 4.7" 61x102mm
[1452607773.472867] mirserver:        Current mode 768x1280 60.00Hz
[1452607773.472959] mirserver:        Preferred mode 768x1280 60.00Hz
[1452607773.473050] mirserver:        Logical position +0+0
[1452607773.481169] mirserver:   0.2: DisplayPort 0.0" 0x0mm
[1452607773.484465] mirserver:        Current mode 1920x1080 60.00Hz
[1452607773.484678] mirserver:        Preferred mode 1920x1080 60.00Hz
[1452607773.484861] mirserver:        Logical position +768+0
Surface occluded
Surface exposed
[1452607773.721761] perf: mir_demo_client_egltriangle: 52.63 FPS, render time 1.96ms, buffer lag 54.26ms (3 buffers)
[1452607773.723226] perf: Mir nested display for output #1: 51.63 FPS, render time 9.35ms, buffer lag 49.04ms (3 buffers)
[1452607774.616099] perf: Mir nested display for output #2: 38.42 FPS, render time 418720.76ms, buffer lag 48.37ms (3 buffers)
[1452607774.721913] perf: mir_demo_client_egltriangle: 42.00 FPS, render time 8.06ms, buffer lag 63.71ms (3 buffers)
[1452607774.742789] perf: Mir nested display for output #1: 41.21 FPS, render time 23.11ms, buffer lag 48.90ms (3 buffers)
[1452607775.621654] perf: Mir nested display for output #2: 37.81 FPS, render time 25.47ms, buffer lag 53.59ms (3 buffers)
[1452607775.744651] perf: Mir nested display for output #1: 40.95 FPS, render time 23.05ms, buffer lag 49.83ms (3 buffers)
[1452607775.747733] perf: mir_demo_client_egltriangle: 40.97 FPS, render time 8.42ms, buffer lag 64.58ms (3 buffers)
[1452607776.664474] perf: Mir nested display for output #2: 37.42 FPS, render time 26.29ms, buffer lag 52.78ms (3 buffers)
[1452607776.745048] perf: Mir nested display for output #1: 42.00 FPS, render time 22.35ms, buffer lag 49.15ms (3 buffers)
[1452607776.765832] perf: mir_demo_client_egltriangle: 42.23 FPS, render time 7.41ms, buffer lag 64.04ms (3 buffers)
[1452607777.675553] perf: Mir nested display for output #2: 39.56 FPS, render time 24.56ms, buffer lag 52.31ms (3 buffers)
[1452607777.745139] perf: Mir nested display for output #1: 39.00 FPS, render time 24.83ms, buffer lag 53.03ms (3 buffers)
[1452607777.777125] perf: mir_demo_client_egltriangle: 38.57 FPS, render time 9.35ms, buffer lag 68.07ms (3 buffers)
[1452607778.696642] perf: Mir nested display for output #2: 38.19 FPS, render time 25.50ms, buffer lag 53.28ms (3 buffers)
[1452607778.778803] perf: Mir nested display for output #1: 39.69 FPS, render time 24.35ms, buffer lag 50.34ms (3 buffers)
[1452607778.794247] perf: mir_demo_client_egltriangle: 40.31 FPS, render time 9.20ms, buffer lag 65.19ms (3 buffers)
[1452607779.701983] perf: Mir nested display for output #2: 38.80 FPS, render time 23.95ms, buffer lag 54.05ms (3 buffers)
[1452607779.781367] perf: Mir nested display for output #1: 38.92 FPS, render time 25.09ms, buffer lag 52.36ms (3 buffers)
[1452607779.796261] perf: mir_demo_client_egltriangle: 38.96 FPS, render time 8.38ms, buffer lag 68.82ms (3 buffers)
[1452607780.716328] perf: Mir nested display for output #2: 38.46 FPS, render time 23.72ms, buffer lag 53.51ms (3 buffers)
[1452607780.796444] perf: Mir nested display for output #1: 39.40 FPS, render time 24.50ms, buffer lag 51.37ms (3 buffers)
[1452607780.829772] perf: mir_demo_client_egltriangle: 38.72 FPS, render time 8.66ms, buffer lag 68.50ms (3 buffers)
[1452607781.723042] perf: Mir nested display for output #2: 39.76 FPS, render time 24.06ms, buffer lag 51.54ms (3 buffers)
[1452607781.801816] perf: Mir nested display for output #1: 42.78 FPS, render time 22.50ms, buffer lag 47.75ms (3 buffers)
[1452607781.853029] perf: mir_demo_client_egltriangle: 43.01 FPS, render time 8.07ms, buffer lag 62.29ms (3 buffers)