Services / Debug processed calls

To receive additional info about processed calls on a specific node, enable debug logging and (optional) profiling.

Enable debug logging

The ValueA framework uses standard logging facilities from python, which are configured in config/log.conf

Tip

A detailed set of options for the python logging facility can be found in the standard docs, which are available here

To enable logging change the level attribute of the desired handler to debug, for example:

[handler_filehandler]
class=FileHandler
level=DEBUG
formatter=format01
args=('log/backend.log',)

Next restart the daemon (when running on a server, otherwise stop/start the listener), using:

username@ubuntu:~$ service message_broker.rc restart

Enable detailed message logging

Sometimes it’s practical to be able to track all incoming and outgoing messages, to flush all messages into a separate file, use the following configuration:

[loggers]
**keys=....,valueamsg,....**

[logger_valueamsg]
level=DEBUG
handlers=filehandlerMessages
**qualname=valuea.messages**
propagate=0

[handler_filehandlerMessages]
class=FileHandler
level=DEBUG
formatter=format03
args=('log/messages.log',)

Note

The loggers section contains all configured loggers, the qualname in logger_valueamsg controles the scope on which messages to catch.

Enable profiler

To enable message profiling, enable the “profile” tag (set to True) in the worker process you want to profile, located in config/broker.conf.

Next restart the daemon.

When both debug logging and profiling are enabled, you can use the debug log to find the message id and locate the profile information.

For example, these log entries:

[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:53,902 DEBUG handle request e6a852ac-4d10-4fc9-93e9-4ec1fad7f161 for uri /test/test1/put_timeseries  (__anonymous__)
[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:54,155 DEBUG validate message e6a852ac-4d10-4fc9-93e9-4ec1fad7f161
[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:54,156 DEBUG authenticate e6a852ac-4d10-4fc9-93e9-4ec1fad7f161 ( valuea.test.put_timeseries / __anonymous__ )
[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:54,159 DEBUG service.set_message e6a852ac-4d10-4fc9-93e9-4ec1fad7f161
[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:54,160 DEBUG execute valuea.test.put_timeseries e6a852ac-4d10-4fc9-93e9-4ec1fad7f161
[__main__.handler] [ pid:7468 ] 2015-10-24 12:00:54,491 DEBUG done e6a852ac-4d10-4fc9-93e9-4ec1fad7f161 in 0.59 seconds (__anonymous__)

results in a file log/profile/e6a852ac-4d10-4fc9-93e9-4ec1fad7f161.profile being created.

To visualize this, you need to have both graphviz and gprof2dot installed, then you can easy convert a trace to a svg (or other) diagram.

gprof2dot -f pstats  e6a852ac-4d10-4fc9-93e9-4ec1fad7f161.profile   | dot -Tsvg -o  e6a852ac-4d10-4fc9-93e9-4ec1fad7f161.svg

An overview of the function calls is also recorded as part of the profiler, this output will use the .profile.text extension (example : 41b28c13-7498-4dbb-bbd8-e322ad65a5aa.profile.text) and contains the following fields:

  • ncalls

    • for the number of calls,

  • tottime

    • for the total time spent in the given function (and excluding time made in calls to sub-functions)

  • percall

    • is the quotient of tottime divided by ncalls

  • cumtime

    • is the cumulative time spent in this and all subfunctions (from invocation till exit). This figure is accurate even for recursive functions.

  • percall

    • is the quotient of cumtime divided by primitive calls

  • filename:lineno(function)

    • provides the respective data of each function