Logging

20#20

A log file has the structure outlined in the following example (from test/bpnn.py):

11:33:53.19  Logging started, 12/22/02                  %%%%%%%%%%%%%%%%%%%%
11:33:53.29  ActivePassiveProfiler: starting                           %%%%%
11:33:53.40   ______
        #1   |95.1 %|  active_start              ...psyco\profiler.py:258
        #2   | 0.9 %|  ?                         ...\lib\traceback.py:1
        #3   | 0.8 %|  ?                                      bpnn.py:8
        #4   | 0.7 %|  time                                   bpnn.py:22
        #5   | 0.4 %|  seed                      ...222\lib\random.py:140
        #6   | 0.3 %|  ?                         ...\lib\linecache.py:6
        #7   | 0.3 %|  write                     ...s\psyco\logger.py:22
        #8   | 0.3 %|  __init__                               bpnn.py:48
        #9   | 0.2 %|  go                        ...psyco\profiler.py:31
11:33:53.62  tag function: backPropagate                                   %
11:33:53.62  tag function: update                                          %
11:33:53.67  tag function: train                                           %
11:33:54.12   ______
        #1   |58.4 %|  active_start              ...psyco\profiler.py:258
        #2   | 2.5 %|  random                    ...222\lib\random.py:168
        #3   | 2.1 %|  __init__                               bpnn.py:48
        #4   | 2.1 %|  demo                                   bpnn.py:167
        #5   | 2.0 %|  dumpcharges               ...s\psyco\logger.py:56
        #6   | 1.2 %|  do_profile                ...psyco\profiler.py:299
        #7   | 1.2 %|  rand                                   bpnn.py:36
        #8   | 0.9 %|  makeMatrix                             bpnn.py:40
        #9   | 0.8 %|  time                                   bpnn.py:22
        #10  | 0.6 %|  ?                                      bpnn.py:8
(...cut...)
11:33:55.50   ______
        #1   |42.5 %|  active_start              ...psyco\profiler.py:258
        #2   | 8.3 %|  random                    ...222\lib\random.py:168
        #3   | 6.7 %|  dumpcharges               ...s\psyco\logger.py:56
        #4   | 6.6 %|  __init__                               bpnn.py:48
        #5   | 4.0 %|  rand                                   bpnn.py:36
        #6   | 3.4 %|  demo                                   bpnn.py:167
        #7   | 2.9 %|  makeMatrix                             bpnn.py:40
        #8   | 2.3 %|  do_profile                ...psyco\profiler.py:299
        #9   | 1.3 %|  time                                   bpnn.py:22
        #10  | 1.0 %|  test                                   bpnn.py:140
11:33:55.50  tag function: random                                          %
11:33:55.94  memory usage: 220+ kb                                         %
11:33:55.94  program exit, 12/22/02                     %%%%%%%%%%%%%%%%%%%%

The first column is a time (hours, minutes, seconds, hundredths). Most lines end in a number of percent signs; the more percent signs, the more important the line is, so that you can for example do a grep %%% bpnn.log-psyco to see the lines of importance 3 or more. As an exception, lines produced by the Psyco C core (as opposed to the Python glue, e.g. the profiler logic) end in % % (percent, space, percent).

The most common lines you will find in logs are:

#1, #2, #3,...

List (on several lines) of the functions which currently have the highest charge. You can typically use this to tune the watermark (section ). The displayed list is limited to the first 10 items by default; this can be customized with the top argument of psyco.log.

memory usage: x+ kb

Psyco's current notion of how much memory is consumes for the emitted machine code and supporting data structures. This is a rouch estimation of the memory overhead (the + sign is supposed to remind you that this figure is highly underestimated). Use this info to tune the memory limits (section ).

unsupported opcode x at y:z

The function y cannot be compiled. Look up the opcode number x in the table of appendix .

tag function: x

The function charge has reached the watermark. Its code object is compiled. Execution of the function goes on in the compiled version.

bind function: x

The function charge has reached the watermark and it is bound (with psyco.bind). Only when function tagging is impossible (when doing passive profiling only). Bound functions are only compiled the next time the function is called, which means that any work that is still done before the current call returns will be done uncompiled. The profiler will continue to charge the function for that work and possibly bind the same function several times (with no bad consequences).

cannot find function x in y

The profiler's attempt to use psyco.bind failed because the function object could not be found. Indeed, the profiler charges code objects, and psyco.bind only applies to function objects. Looking for a function when we only have the code object is difficult (not to mention that some code objects may have been created by compile or execfile and are not owned by any function whatsoever). Psyco currently only locates the functions defined at the module top-level and the methods of top-level classes. (This is one reason why profilers tag and don't bind if they can.)

profiling stopped, binding n functions

When active profiling stops, the profiler calls psyco.bind on all currently tagged functions. If you feel that this operation is too heavy (e.g. makes a visible pause in your real-time application) use the psyco.runonly profiler to prevent this from occuring. Normally it only applies if you have set limits on all the profilers queued so far.

disabled (L limit reached)

The profiler is stopped because it reached the limit L. The next queued profiler can start.

disabled by psyco.error

Failed to set the profiling or tracing hooks. Normally means that some other code (e.g. a debugger) is already using them. Psyco profiling will restart when the other program let go of the hooks.

resetting stats

Profiling charges are reset to zero. Occurs periodically.

no locals() in functions bound by Psyco

Logged the first time the corresponding psyco.warning is issued. This is just a reminder. To locate the problem, use the information Python prints to the terminal.

unsupported ** argument in call to x

The call to the function x cannot be compiled because of the ** argument. This is a limitation of Psyco; try to avoid ** arguments (or write to me and insist on this feature).

unsupported free or cell vars in x

Psyco currently cannot compile functions that use nested scopes.