dispmanx vsync callback is called 4 times per frame

[ali1234]

The following example runs for 1 second and measures the time between calls to the vsync callback in microseconds. With PAL composite out, the time between each call should be 20000 microseconds if the vsync happens per field.

The callback fires correctly about 20 times, then it starts firing 4 times per field. Same happens when using HDMI output.

Test code:

#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <time.h>
#include <assert.h>
#include <unistd.h>
#include <sys/time.h>

#include "bcm_host.h"

static DISPMANX_DISPLAY_HANDLE_T   display;
unsigned long lasttime = 0;

void vsync(DISPMANX_UPDATE_HANDLE_T u, void* arg) {
    struct timeval tv;
    gettimeofday(&tv, NULL);
    unsigned long microseconds = (tv.tv_sec*1000000)+tv.tv_usec;
    printf("sync %lu\n", microseconds-lasttime);
    lasttime = microseconds;
}

int main(void)
{
    bcm_host_init();
    display = vc_dispmanx_display_open( 0 );

    vc_dispmanx_vsync_callback(display, vsync, NULL);
    sleep(1);
    vc_dispmanx_vsync_callback(display, NULL, NULL); // disable callback

    vc_dispmanx_display_close( display );
    return 0;
}

Output:

sync 1084946804
sync 19968
sync 19949
sync 20027
sync 19964
sync 20056
sync 19934
sync 20069
sync 19936
sync 20026
sync 19992
sync 20050
sync 19945
sync 20019
sync 19989
sync 20031
sync 19934
sync 20025
sync 19978
sync 20053
sync 19974
sync 20070
sync 200
sync 136
sync 56
sync 19585
sync 202
sync 137
sync 56
sync 19610
sync 202
sync 135
sync 55
sync 19574
sync 206
sync 137
sync 50
sync 19665
sync 194
sync 132
sync 56
sync 19561
sync 203
sync 137
sync 52
sync 19638
sync 203
sync 136
sync 52
sync 19600
sync 203
sync 132
sync 52
sync 19624
sync 200
sync 138
sync 52
sync 19573
sync 203
sync 135
sync 52
sync 19664
sync 200
sync 137
sync 56
sync 19565
sync 203
sync 132
sync 53
sync 19630
sync 202
sync 134
sync 52
sync 19603
sync 200
sync 133
sync 52
sync 19632
sync 203
sync 136
sync 52
sync 19572
sync 197
sync 139
sync 52
sync 19671
sync 200
sync 134
sync 53
sync 19561
sync 198
sync 138
sync 52
sync 19634
sync 200
sync 135
sync 52
sync 19612
sync 204
sync 134
sync 54
sync 19618
sync 202
sync 131
sync 52
sync 19579
sync 197
sync 136
sync 54
sync 19669
sync 202
sync 134
sync 52
sync 19563
sync 195
sync 135
sync 54
sync 19640
sync 198
sync 134
sync 51
sync 19608
sync 199
sync 142
sync 52
sync 19622
sync 204
sync 135
sync 52
sync 19568
sync 198
sync 134
sync 55
sync 19655
sync 202
sync 133
sync 52

[AndrewFromMelbourne]

Hi I think this should be reported in the firmware repository (https://github.com/raspberrypi/firmware/issues) rather than userland. Having said that I can see a similar issue. I wrote the following when the vsync_callback was first added.

#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <sys/time.h>

#include "bcm_host.h"

volatile uint32_t count = 0;

void
vsync_callback(
    DISPMANX_UPDATE_HANDLE_T update,
    void *arg)
{
    ++count;
}

int
main(void)
{
    struct timeval startTime;
    struct timeval endTime;
    struct timeval diffTime;

    bcm_host_init();

    DISPMANX_DISPLAY_HANDLE_T display = vc_dispmanx_display_open(0);

    vc_dispmanx_vsync_callback(display, vsync_callback, NULL);

    gettimeofday(&startTime, NULL);

    while (1)
    {
        sleep(1);

        gettimeofday(&endTime, NULL);
        timersub(&endTime, &startTime, &diffTime);

        double fps = count/(diffTime.tv_sec+(diffTime.tv_usec/1000000.0));
        printf("fps = %0.1f\n", fps);
    }

    return 0;
}

When run, it would reliably print out fps=50.0 (pal composite display). When I relinked it today (after rebuilding)

fps = 51.0
fps = 69.0
fps = 79.3
fps = 84.4
fps = 87.5
fps = 89.6
fps = 91.1
fps = 92.2
fps = 93.0
fps = 93.7
fps = 94.3
fps = 94.8
fps = 95.2
fps = 95.5
fps = 95.8
fps = 96.1
fps = 96.3
fps = 96.5
fps = 96.7
fps = 96.8
fps = 97.0
fps = 97.1
fps = 97.2
fps = 97.4
fps = 97.5
fps = 97.5
fps = 97.7
fps = 97.8
fps = 97.9
fps = 97.9
fps = 98.0
fps = 98.1
fps = 98.1
fps = 98.2
fps = 98.2
fps = 98.3
fps = 98.3

firmware version

Feb  4 2015 21:07:39 
Copyright (c) 2012 Broadcom
version 115f63aa0915cdb5b6dff23822eb16699b72ae8b (clean) (release)

[AndrewFromMelbourne]

Actually, after a firmware update and a reboot, it went back to working as I expected

fps = 50.0
fps = 50.0
fps = 50.0
fps = 50.0
fps = 50.0

I do wonder about your code. The printf in the callback may cause some problems.

[cleverca22]

i had done similar code using GPIO

void vsync(DISPMANX_UPDATE_HANDLE_T u, void* arg) {
        FILE *fh = fopen("/sys/class/gpio/gpio4/value","w");
        fwrite("1\n",3,1,fh);
        fclose(fh);
        fh = fopen("/sys/class/gpio/gpio4/value","w");
        fwrite("0\n",3,1,fh);
        fclose(fh);
}

https://www.dropbox.com/s/d4na2naqjlidrzm/20150206_184717.jpg?dl=0

top trace is the gpio pin, showing several callbacks per frame, bottom is the raw composite video, v-sync is over the E in peakdet

and if i switch to single sweep mode i can confirm the timings ali1234 saw, the first 9 fields have 1 callback each, then it starts to go nuts

[ali1234]

After firmware update it works for me too.

I'm now on:
'''
Jan 30 2015 18:25:11
Copyright (c) 2012 Broadcom
version d6e004c61a7a749897c482c860d0b2c28196437e (clean) (release)
'''

[cleverca22]

same here, jan 20th was broken, feb 7th works
wait no, let me test this more...

[cleverca22]

yeah, i see the problem now

vc_dispmanx_vsync_callback(vars->display,NULL,NULL)

if you forget to turn the vsync off with this (or the app crashes), you get an extra callback next time you run the app

so the 1st time you run it, 1 call per field
the 2nd time you run it, 2 calls per field, and so on

this explains why it always vanished after a reboot

i have a feeling that 2 apps using v-sync at once will likely also cause the issue, and that is a valid use case, ali1234 would be outputing teletext in the VBI while something else (3d, omx?) does v-sync

[ali1234]

And if you run two programs at the same time that listen for vsync, the first one gets no callbacks and the second one gets two. (Most likely it's just random/race condition which app gets the event.)

[ali1234]

Also as soon as any app calls

vc_dispmanx_vsync_callback(vars->display,NULL,NULL)

ALL callbacks stop firing in all apps.

[popcornmix]

Please run rpi-update and test.

[ali1234]

Feb 12 2015 17:27:39
Copyright (c) 2012 Broadcom
version 571f5d2143489e4300d7e2ed5b1a73f33f3b13e5 (clean) (release)

Identical behaviour.

On 12 February 2015 at 18:10, popcornmix [email protected] wrote:

Please run rpi-update and test.

—
Reply to this email directly or view it on GitHub
#218 (comment)
.

Alistair Buxton
[email protected]

[ali1234]

Actually the vsync is cleaned up on exit automatically now, but if two apps register a callback, one of them still gets two events, and clearing the callback still clears it for all apps.

[popcornmix]

Latest rpi-firmware code has an update to fix an issue with mulitple apps registering vsync callbacks. Can you test?

[ali1234]

Looks like it is fixed. Multiple programs can now vsync, and don't steal messages from each other. Forgetting to unregister the callback at exit also doesn't seem to cause any problems.

[popcornmix]

Okay to close?