classification
Title: pstats: sub-millisecond display
Type: enhancement Stage: patch review
Components: Library (Lib) Versions: Python 3.5
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Romuald, georg.brandl, haypo, serhiy.storchaka
Priority: normal Keywords: patch

Created on 2015-04-30 16:27 by Romuald, last changed 2017-10-12 14:58 by haypo.

Files
File name Uploaded Description Edit
pstats-microseconds.patch Romuald, 2015-04-30 16:27 review
Pull Requests
URL Status Linked Edit
PR 3931 open python-dev, 2017-10-09 13:32
Messages (5)
msg242277 - (view) Author: Romuald Brunet (Romuald) * Date: 2015-04-30 16:27
When running pstats with functions that take less than 0.5 millisecond (per call for example), the value shown is '0.000, which isn't really helpful.

This patch aims to show the value in microseconds instead of seconds for values that would otherwise be displayed as '0.000'

(the display may have to be tweaked for non-utf8 users, as the µ character is used)


Example output:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     9827    0.007      7µs    0.007      7µs {method 'get' of 'dict' objects}
     3427    0.009     25µs    0.017     49µs {map}
    10701    0.006      5µs    0.006      5µs {method 'lower' of 'str' objects}
    31410    0.045     14µs    0.045     14µs {method 'split' of 'str' objects}
    10023    0.006      6µs    0.006      6µs {_weakref.proxy}
    31801    0.009      2µs    0.009      2µs {len}
     3892    0.003      7µs    0.003      7µs {method 'extend' of 'list' objects}
     1397    0.001      8µs    0.001      8µs {method 'replace' of 'str' objects}
    10488    0.010      9µs    0.010      9µs {method 'string_literal' of '_mysql.connection' objects}
    10702    2.620   2447µs    2.620   2447µs {method 'readline' of 'file' objects}
    10023    0.004      3µs    0.004      3µs {method 'info' of '_mysql.connection' objects}
    10023    0.005      5µs    0.005      5µs {method 'insert_id' of '_mysql.connection' objects}
    14327    0.022     15µs    0.022     15µs {method 'rstrip' of 'str' objects}
msg303966 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 15:00
Hum, "2447µs" makes the output more difficult to parse (by a program) and to read (by a human). Why not always displaying 6 digits (after the dot) for the two "percall" columns.
msg303981 - (view) Author: Romuald Brunet (Romuald) * Date: 2017-10-09 15:58
I figured we didn't want to change the size of the columns (+12 COL), but this could easily be done yes
msg304248 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-10-12 14:52
I concur with Victor. This change likely breaks graphical viewers of pstat data.

How gprof and similar tools solve the problem of outputting sub-millisecond timings?
msg304249 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-12 14:58
> I concur with Victor. This change likely breaks graphical viewers of pstat data.

I propose to *do* break the format by always displaying percall timings with a precision of 6 digits.
History
Date User Action Args
2017-10-12 14:58:05hayposetmessages: + msg304249
2017-10-12 14:52:51serhiy.storchakasetmessages: + msg304248
2017-10-12 14:52:35serhiy.storchakasetmessages: - msg304247
2017-10-12 14:51:47serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg304247
2017-10-09 15:58:38Romualdsetmessages: + msg303981
2017-10-09 15:00:43hayposetnosy: + haypo
messages: + msg303966
2017-10-09 13:32:50python-devsetpull_requests: + pull_request3906
2015-04-30 21:30:19ned.deilysetnosy: + georg.brandl
stage: patch review

versions: + Python 3.5
2015-04-30 16:27:51Romualdcreate