Show timestamp for print calls / use logging

[gabrieleiannetti]

Hi,

it would be very helpful, if timestamps would be provided to print calls.

Anyway, I would suggest to directly use a logger for info and error messages.

Best Gabriele

[guilbaults]

A better way would be to use the python profiler to see what part is slow. This should show up if the regex is slow, or simply printing the results. I can see that running the subprocess takes about 2 sec, and parsing the result of all switches takes about 0.5s (infiniband-exporter.py:217(parse_switch))

python -m cProfile -s cumulative infiniband-exporter.py --port 8080 --node-name-map /etc/node-name-map
^C         2227682 function calls (2226113 primitive calls) in 7.632 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.002    0.002    7.633    7.633 infiniband-exporter.py:1(<module>)
        1    0.000    0.000    7.557    7.557 SocketServer.py:221(serve_forever)
        1    0.000    0.000    4.072    4.072 SocketServer.py:282(_handle_request_noblock)
        1    0.000    0.000    4.072    4.072 SocketServer.py:315(process_request)
        1    0.000    0.000    4.072    4.072 SocketServer.py:332(finish_request)
        1    0.000    0.000    4.072    4.072 SocketServer.py:643(__init__)
        1    0.000    0.000    4.072    4.072 simple_server.py:113(handle)
        1    0.001    0.001    4.071    4.071 handlers.py:76(run)
        1    0.008    0.008    4.062    4.062 exposition.py:39(prometheus_app)
        1    0.166    0.166    4.054    4.054 exposition.py:70(generate_latest)
        8    0.000    0.000    3.484    0.435 SocketServer.py:151(_eintr_retry)
        8    3.483    0.435    3.483    0.435 {select.select}
       26    0.004    0.000    2.675    0.103 infiniband-exporter.py:256(collect)
        1    0.000    0.000    2.093    2.093 subprocess.py:769(communicate)
        1    0.000    0.000    2.093    2.093 subprocess.py:1392(_communicate)
        1    0.003    0.003    2.090    2.090 subprocess.py:1425(_communicate_with_poll)
      309    2.082    0.007    2.082    0.007 {built-in method poll}
    45917    0.384    0.000    1.151    0.000 exposition.py:73(sample_line)
     2096    0.112    0.000    0.538    0.000 infiniband-exporter.py:217(parse_switch)
   367365    0.374    0.000    0.374    0.000 {method 'format' of 'unicode' objects}
    41741    0.130    0.000    0.211    0.000 metrics_core.py:109(add_metric)
   826477    0.157    0.000    0.157    0.000 {method 'replace' of 'unicode' objects}
    45917    0.072    0.000    0.127    0.000 utils.py:7(floatToGoString)
     2096    0.042    0.000    0.119    0.000 infiniband-exporter.py:183(parse_counter)
    22754    0.014    0.000    0.087    0.000 re.py:139(search)
        1    0.001    0.001    0.063    0.063 __init__.py:3(<module>)
    22754    0.053    0.000    0.053    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
    45915    0.051    0.000    0.051    0.000 {method 'join' of 'unicode' objects}
[...]

[gabrieleiannetti]

Hi,

it is more about getting the exact timestamps when something is printed out by the program.

For instance, we get errors printed on stderr, which come from ibqueryerrors.
Since the exporter is executed cyclically, it would be helpful to know, when a message was printed.

Best
Gabriele

[guilbaults]

Hi, check this pull request, it should fix this issue: https://github.com/guilbaults/infiniband-exporter/pull/11

[gabrieleiannetti]

Hi,

thanks for adding logging.

I have just one thing... If there is a 'End of collection cycle' there should be a 'Start of collection cycle'.

Best Gabriele

[guilbaults]

Merged