CODEWITHSUNDEEP
pythonapp-engine-flexible
Valentin Coudert
Valentin Coudert

Reputation: 1919

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

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.

enter image description here This is just after entering my function (it's actually my route handler)

enter image description here 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

Upvotes: 0

Views: 64

Answers (1)

Buckors
Buckors

Reputation: 40

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.

Upvotes: 1

Related Questions