Very different times between time.clock() and App Engine log time

Question

I try to troubleshoot latency issues in my App Engine flex app, and I suspect that my server takes way too long to answer (the TTFB, given by Chrome, is more than 20sec).

So I use time.clock() (Python2.7) to see where the time is spent. I also use print to get those values into Stackdriver.

And the different times are not consistent at all.

This is just after entering my function (it's actually my route handler)

And here is just before leaving it.
The elapsed time I compute is nothing but end time - start time (one call to time.clock() each).

And you can see it gives less than one sec. The stackdriver logs show that almost 4 sec is spent.

Any idea why this difference ? time.clock() isn't working as expected on App engine flex ?

Thanks

Answer 1

time.clock() is giving you the amount of CPU time of the process and that is why the values are inconsistent.

I did this test:

@app.route('/')
def hello():
    """Return a friendly HTTP greeting."""
    tc0 = time.clock()
    print(tc0)
    tt0 = time.time()
    print(tt0)
    x= datetime.datetime.now()
    print(x)

    time.sleep(10)

    tc1 = time.clock()
    print(tc1)
    tt1 = time.time()
    print(tt1)
    y = datetime.datetime.now()
    print(y)

    return 'Hello World!'

And this are the results:

tc0  0.144582
tt0  1552994288.7333689
x    2019-03-19 11:18:08.733498

tc1  0.144829
tt1  1552994298.7438576
y    2019-03-19 11:18:18.743877

As you can see, what you want to use is time.time() or datetime.datetime.now() to get the real time spent in a given portion of code since time.clock() is giving you the amount of CPU time.