importing Window seems to clobber kivy.clock.Clock.schedule_once() in some way

[janssen]

I'm trying to use Clock to schedule my app startup after the display of an animated splash screen, but the timing of schedule_once() seems almost random.

Here's a program that illustrates the buggy behavior:

from kivy.base import EventLoop
from kivy.clock import Clock
from kivy.core.window import Window

import time

def callback2(*args):
    print '2', time.time()

def callback1(*args):
    print '1', time.time()
    Clock.schedule_once(callback2, 2.0)

print 'start', time.time()
Clock.schedule_once(callback1, 3.0)
EventLoop.run()

Here's a run of this simple program. Note that the first callback is supposed to occur after 3 seconds, but actually occurs after about 1.8 seconds.

% python t.py
[INFO              ] [Logger      ] Record log in /home/wjanssen/.kivy/logs/kivy_16-03-18_70.txt
[INFO              ] [Kivy        ] v1.9.1
[INFO              ] [Python      ] v2.7.11 |Continuum Analytics, Inc.| (default, Dec  6 2015, 18:08:32) 
[GCC 4.4.7 20120313 (Red Hat 4.4.7-1)]
[INFO              ] [Factory     ] 179 symbols loaded
[INFO              ] [Image       ] Providers: img_tex, img_dds, img_gif, img_sdl2 (img_pil, img_ffpyplayer ignored)
[INFO              ] [OSC         ] using <multiprocessing> for socket
[INFO              ] [Window      ] Provider: sdl2(['window_egl_rpi'] ignored)
[INFO              ] [GL          ] OpenGL version <3.0 Mesa 11.0.2>
[INFO              ] [GL          ] OpenGL vendor <nouveau>
[INFO              ] [GL          ] OpenGL renderer <Gallium 0.4 on NV96>
[INFO              ] [GL          ] OpenGL parsed version: 3, 0
[INFO              ] [GL          ] Shading version <1.30>
[INFO              ] [GL          ] Texture max size <8192>
[INFO              ] [GL          ] Texture max units <16>
[INFO              ] [Window      ] auto add sdl2 input provider
[INFO              ] [Window      ] virtual keyboard not allowed, single mode, not docked
start 1458352985.62
1 1458352987.44
2 1458352989.44
Killed
% 

If we replace Window with a simple dummy event listener:

from kivy.base import EventLoop
from kivy.clock import Clock

class Listener(object):
    def dispatch(self, *args):
        pass

listener = Listener()

EventLoop.add_event_listener(listener)

import time

def callback2(*args):
    print '2', time.time()

def callback1(*args):
    print '1', time.time()
    Clock.schedule_once(callback2, 2.0)

print 'start', time.time()
Clock.schedule_once(callback1, 3.0)
EventLoop.run()

the timing is more or less what we expect:

% python t.py
[INFO              ] [Logger      ] Record log in /home/wjanssen/.kivy/logs/kivy_16-03-18_71.txt
[INFO              ] [Kivy        ] v1.9.1
[INFO              ] [Python      ] v2.7.11 |Continuum Analytics, Inc.| (default, Dec  6 2015, 18:08:32) 
[GCC 4.4.7 20120313 (Red Hat 4.4.7-1)]
[INFO              ] [Factory     ] 179 symbols loaded
start 1458353421.51
1 1458353424.41
2 1458353426.42
% 

[dessant]

I can reproduce your behavior, I've edited your example a bit so it's easier to compare results.

from kivy.base import EventLoop
from kivy.clock import Clock
from kivy.core.window import Window

import time

def callback2(*args):
    second = time.time()
    print('2', second - start)

def callback1(*args):
    first = time.time()
    print('1', first - start)
    Clock.schedule_once(callback2, 2.0)

start = time.time()
Clock.schedule_once(callback1, 3.0)
EventLoop.run()

1 2.1312689781188965
2 4.134382009506226

[janssen]

I looked at the code, but I couldn't see anything obvious. I was testing on Darwin.

[dessant]

I'm on Windows, it's probably universal.

[akshayaurora]

Can you test with Clock.get_time() instead of time.time().

That would be a more accurate time as it starts from when the Kivy.Clock initiates i.e after the event loop initiates. As time.time() is from when python time instance started

[akshayaurora]

Using https://kivy.org/docs/api-kivy.clock.html#kivy.clock.ClockBase.get_boottime

Running the following example::

from kivy.base import EventLoop
from kivy.clock import Clock
from kivy.core.window import Window

def callback2(*args):
    print('2', Clock.get_boottime())

def callback1(*args):
    print('1', Clock.get_boottime())
    Clock.schedule_once(callback2, 2.0)

Clock.schedule_once(callback1, 3.0)
EventLoop.run()

I get::

('1', 2.99849796295166)
('2', 4.9996349811553955)

[janssen]

That program hide the problem, though. The problem is that the first schedule_once does not get triggered 3 seconds after it's set. Even if you use Clock.get_boottime(). Here's another example:

import time
from kivy.base import EventLoop
from kivy.clock import Clock
from kivy.core.window import Window

def callback2(*args):
    global starttime
    print('2', Clock.get_boottime(), time.time() - starttime)
    EventLoop.quit = True

def callback1(*args):
    global starttime
    print('1', Clock.get_boottime(), time.time() - starttime)
    Clock.schedule_once(callback2, 2.0)

starttime = time.time()
print('0', Clock.get_boottime(), starttime)
Clock.schedule_once(callback1, Clock.get_boottime() + 3.0)
EventLoop.run()

With this, I get:

('0', 0.0, 1459278846.490209)
('1', 3.0041370391845703, 2.559940814971924)
('2', 5.008002996444702, 4.563763856887817)

[dessant]

I've been told that scheduling before the event loop is started could be unsafe, we should also look into that.

Let's reopen this, if the behavior turns out to be expected, we could document it.

[dessant]

We had a discussion with the team, @akshayaurora and @Kovak proposed to explicitly drop schedules created before the clock has started.

[janssen]

When is the clock started? When EventLoop.run() is called? Can you then schedule something after you've called it? And, out of curiosity, why doesn' t this odd behavior happen if you register a user event listener, instead of loading Window?

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.