Libfaketime does not appear to affect time.monotonic_ns in python3

[thetazero]

Would really appreciate some help getting to the bottom of this.

Given the file test.py

import time

_start = time.monotonic_ns()

while time.monotonic_ns() - _start < 1e9:
    pass

print('done')

Running this: time env FAKETIME_NO_CACHE=1 FAKETIME="x10" LD_PRELOAD="/usr/lib/x86_64-linux-gnu/faketime/libfaketime.so.1" python3 test.py

Outputs this:

done
1.04user 0.01system 0:01.05elapsed 99%CPU (0avgtext+0avgdata 9160maxresident)k
0inputs+0outputs (1major+1114minor)pagefaults 0swaps

While running this: time env FAKETIME_NO_CACHE=1 FAKETIME="x10" LD_PRELOAD="/usr/lib/x86_64-linux-gnu/faketime/libfaketime.so.1" sleep 1

Outputs this:

0.00user 0.00system 0:00.10elapsed 0%CPU (0avgtext+0avgdata 2740maxresident)k
0inputs+0outputs (0major+139minor)pagefaults 0swaps

Both should take 0.1 seconds of time to execute, however for some reason only sleep 1 appears affected (takes 0.1 seconds to execute as expected), while the python version does not seem to be affected.

[wolfcw]

Does libfaketime work for other time- / sleep-related Python functions in your environment?

If only time.monotonic_ns() is affected, it'd be great to know which underlying system call the time module uses in Python, as probably libfaketime does not intercept it yet. I didn't spot that detail by skimming the documentation, so eventually it has to be found in the implementation itself.

[thetazero]

It works for something like time.sleep(1) (my environment is Ubuntu 22.04 if it helps).

In my case it seems to all stem down to a py_get_monotonic_clock call, which in my environment should boil down to a clock_gettime call.

Here is the monotonic_ns source if you are interested in digging through it yourself.

Let me know if there's any more information I can help find

[wolfcw]

In your example, could you please change FAKETIME="x10" to FAKETIME="-0 x10" and check whether that changes anything?

[thetazero]

Oh, that actually changed a lot for the version using monotonic_ns: Here are the results:

done

real    0m0.211s
user    0m0.191s
sys     0m0.020s

I suspect the passing is causing some issues (only 5x speed up rather than 10x), but this might be the solution

Thank you so much

[thetazero]

To further my previous comment: Results at 0.5x Speed:

real    0m2.114s
user    0m2.086s
sys     0m0.028s

Results at 2x Speed:

real    0m0.603s
user    0m0.583s
sys     0m0.020s

Results at 5x Speed:

real    0m0.293s
user    0m0.273s
sys     0m0.020s

Results at 20x Speed:

real    0m0.168s
user    0m0.144s
sys     0m0.024s

[wolfcw]

First, it's good to know that the problem is not related to some non-intercepted system call. It rather seems to be a problem parsing FAKETIME values with a speed modifier but without a faketime setting. Not sure why this did not affect the other test case with sleep.

As far as the run-times are concerned, I'm not sure how much of that can be attributed to some internal overhead given that time.monotonic_ns() is probably called awfully often in a loop that does nothing else but Python's pass.

When I change your Python code to wait for 5 seconds instead of 1, and run it at x10 speed, I'm getting a "real" execution time of about 0.532s on my testing machine, and very similar values when I repeat. That's pretty close to what can be expected theoretically. Eventually you might want to measure within the Python script when exactly it exits that loop.

[thetazero]

Yeah, I'm also confused by the sleep/monotonic behavior. I'm not familiar with this library so I can't really comment on that.

I suspect you're right about the delay being due to the internal overhead.

This is perfect for my purposes, and if there's any other additional information you'd like to have please let me know.

Thank you for helping me figure this out.