Method Call Traces for Strus

• Download source (tar with C++ sources of the example trace module introduced) - 12 Kb

Goals

For Java developers, it is quite familiar to use method call traces as instrument of development. Call traces help you to understand what the software does when performing a specific task. They can also help you to find bugs, crashes, endless loops, etc. Besides finding errors, they can help you to statistically analyze behavior by counting specific events. Call traces also make a software transparent. This is especially important for a project like Strus, that has still a very small user base. Transparency can create trust in a software when other peoples' experience is barely available to create this level of trust.

The goal of this article is to show you how to create method call traces in Strus.

Background

Strus is a set of libraries and tools to build search engines. It is split into several small projects (currently 8), one of them called strusTrace. It implements the logging of method call traces.

Introduction

There is no native support in C++ as compiled language for tracing as for example in Java. Tracing is a classical problem you wish to solve as own aspect. How you can bring aspect orientation into a software depends very much on the rules imposed on its components.  For implementing tracing in Strus as own aspect, the following two properties of Strus were used:

1. In Strus every interface is a pure abstract class. This allows to create proxy classes that wrap each method call, and so any access to the class. A proxy can redirect the access to the real implementation while doing something else behind the scenes (like for example to log, what was called).
2. All objects implementing interfaces are created either by a interface method call or by a "root" object. This pattern helps to control the creation of objects and allows wrapping each object created with a proxy instance.

The project strusTrace uses some code generation to implement a proxy for every strus and strusAnalyzer interface class. Finally, the root objects (object builder interface) are wrapped by a proxy implementation.

Using Call Traces

Call trace logging is configured in a string with semicolon (';') separated assignments of configuration variables. One of them is the identifier of the trace logger to use specified with the configuration variable 'log'. Some trace loggers are part of strusTrace. If the standard loggers are not enough, you can define one on your own and load it as a strus module. The following standard trace loggers are predefined:

dump

logs all methods called immediately to a file or to stdout. This logger can be useful for analyzing behavior in the case of a crash or endless loop. The example

log=dump;file=stdout

prints all methods called and the method termination event to stdout.

json

builds a dependency tree of method calls in JSON and writes this tree to a file or stdout. This is a logger that allows you to navigate in a call tree of a terminated Strus run. The example

log=json;file=tree.json

prints the method call tree as JSON tree to a file tree.json.

count

counts all calls of a specific method of a defined class. You can print the total number of calls to a file or stdout or the number of calls grouped by objects implementing a defined interface. The example

log=count;groupby=PostingIterator;count=DatabaseCursor/seekUpperBound;file=stdout

counts the calls of the method seekUpperBound of a DatabaseCursorInterface implementation for any descendant of a PostingIteratorInterface implementation. It outputs a list of lines with pairs of numbers with the object id of the PostingIteratorInterface implementation followed by the number of seekUpperBound calls counted in the context of this object.

breakpoint

calls a function strus_breakpoint when a method is called and the time counter is at a specified value. This method can be used to set a debugger breakpoint at a defined event in a method call trace. The example

log=breakpoint;call=125821

calls the function strus_breakpoint, when the method counter is at 125821. This allows you to start call a program using strus in a debugger and halt execution at the breakpoint defined as a specific event in the call trace.

Call Traces in Language Bindings

To use call traces in language bindings, you have to call the Strus context constructor with an additional string parameter specifying the call trace configuration. Tracing cannot be used in RPC client mode (it does not make sense in an RPC client anyway). For tracing in the RPC context, you can start the RPC server with call tracing configured. Here follows a list of example constructor calls:

Java

Context ctx = new Context( 0, "log=dump;file=stdout");

PHP

$ctx = new StrusContext( 0, "log=dump;file=dump.txt");

Python

ctx = strus.Context( 0, "log=json;file=tree.json" )

Call Traces for Command Line Tools

The strus command line tools like the programs implemented in the project strusUtilities and the RPC server implemented in the project strusRpc can be started with the option -T or --trace followed by the strus trace configuration.

The following example call of strusCreate generates a JSON call tree and prints it to the file tree.json:

strusCreate -T "log=json;file=out.json" -s "path=storage; metadata=doclen UINT16"

and we get:

storage successfully created.

Now let's have a look at the printed file out.json:

{
"calls":[
  {
  "time":1,
  "object":1,
  "class":"StorageObjectBuilder",
  "method":"getDatabase",
  "parameter": ["Database<2>", "path=storage; metadata=doclen UINT16"]
  },
  {
  "time":2,
  "object":1,
  "class":"StorageObjectBuilder",
  "method":"getStorage",
  "parameter": ["Storage<3>"]
  },
  {
  "time":3,
  "object":3,
  "class":"Storage",
  "method":"getConfigParameters",
  "parameter": [[
    "cachedterms"], "CreateClient"]
  },
  {
  "time":4,
  "object":2,
  "class":"Database",
  "method":"getConfigParameters",
  "parameter": [[
    "path",
    "cache",
    "compression",
    "max_open_files",
    "write_buffer_size",
    "block_size"], "CreateClient"]
  },
  {
  "time":5,
  "object":2,
  "class":"Database",
  "method":"createDatabase",
  "parameter": [true, "path=storage; metadata=doclen UINT16"]
  },
  {
  "time":6,
  "object":2,
  "class":"Database",
  "method":"createClient",
  "parameter": ["DatabaseClient<4>", "path=storage; metadata=doclen UINT16"]
  },
  {
  "time":7,
  "object":3,
  "class":"Storage",
  "method":"createStorage",
  "parameter": [true, " metadata=doclen UINT16", "DatabaseClient<4>"],
  "sub": [
    {
    "time":8,
    "object":4,
    "class":"DatabaseClient",
    "method":"createTransaction",
    "parameter": ["DatabaseTransaction<5>"]
    },
    {
    "time":9,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VTermNo", "&#1;"]
    },
    {
    "time":10,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VTypeNo", "&#1;"]
    },
    {
    "time":11,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VDocNo", "&#1;"]
    },
    {
    "time":12,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VAttribNo", "&#1;"]
    },
    {
    "time":13,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VNofDocs", "&#0;"]
    },
    {
    "time":14,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VByteOrderMark", "&#251;&#128;&#160;&#132;&#128;"]
    },
    {
    "time":15,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "VVersion", "\t"]
    },
    {
    "time":16,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"write",
    "parameter": [null, "M", "doclen UInt16"]
    },
    {
    "time":17,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"commit",
    "parameter": [true]
    },
    {
    "time":18,
    "object":5,
    "class":"DatabaseTransaction",
    "method":"Destructor"
    }
  ]
  },
  {
  "time":19,
  "object":4,
  "class":"DatabaseClient",
  "method":"Destructor"
  },
  {
  "time":20,
  "object":1,
  "class":"StorageObjectBuilder",
  "method":"Destructor"
  },
  {
  "time":21,
  "object":2,
  "class":"Database",
  "method":"Destructor"
  },
  {
  "time":22,
  "object":3,
  "class":"Storage",
  "method":"Destructor"
  }
]
}

The output got quite big for a method just creating a storage. You can imagine that an output can get huge, when doing more complicated stuff.

With the trace logger breakpoint, we can now pick one method call of our output log, say the one with time = 14, a method all of DatabaseTransactionInterface::write and call strusCreate with "log=breakpoint;call=14" as trace configuration. If we do this in a debugger, we can halt on this method call by setting a breakpoint to 'strus_breakpoint'.

Writing Your Own Call Trace Loggers

We introduce here an example trace logger implemented as strus module that can be dynamically loaded by a strus program or language binding. All you have to do is to implement the trace logger interface and build it as strus module.

The following code can be downloaded (see download link at the top of this article). It implements a trace logger that counts the number of method calls for each interface classname methodname pair.

#include "strus/base/dll_tags.hpp"
#include "strus/traceModule.hpp"
#include "strus/traceLoggerInterface.hpp"
#include "strus/errorBufferInterface.hpp"
#include <string>
#include <vector>
#include <map>
#include <iostream>

class TraceLoggerExample
    :public strus::TraceLoggerInterface
{
public:
    explicit TraceLoggerExample( strus::ErrorBufferInterface* errorhnd_)
        :m_errorhnd(errorhnd_),m_logcnt(0){}
    virtual ~TraceLoggerExample()
    {
        close();
    }

    virtual strus::TraceLogRecordHandle
        logMethodCall(
            const char* className,
            const char* methodName,
            const strus::TraceObjectId&)
    {
        char methodid[ 256];
        snprintf( methodid, sizeof(methodid), "%s::%s", className, methodName);
        try
        {
            ++m_callcount[ methodid];
            return ++m_logcnt;
        }
        catch (const std::bad_alloc&)
        {
            m_errorhnd->report( "out of memory");
            return 0;
        }
    }

    virtual void logMethodTermination(
            const strus::TraceLogRecordHandle& ,
            const std::vector<strus::TraceElement>& )
    {}

    virtual bool close()
    {
        try
        {
            std::map<std::string,int>::const_iterator
                    ci = m_callcount.begin(), ce = m_callcount.end();
            for (; ci != ce; ++ci)
            {
                std::cout << ci->first << " called " << ci->second << " times" << std::endl;
            }
            return true;
        }
        catch (const std::bad_alloc&)
        {
            m_errorhnd->report( "out of memory");
            return false;
        }
    }

private:
    strus::ErrorBufferInterface* m_errorhnd;
    std::map<std::string,int> m_callcount;
    strus::TraceLogRecordHandle m_logcnt;
};

static strus::TraceLoggerInterface* createTraceLogger_example(
              const std::string& ,
              strus::ErrorBufferInterface* errorhnd)
{
    try
    {
        return new TraceLoggerExample( errorhnd);
    }
    catch (const std::bad_alloc&)
    {
        errorhnd->report( "out of memory");
        return 0;
    }
}

static const strus::TraceLoggerConstructor tracelogger[] =
{
    {"traceexample", &createTraceLogger_example},
    {0,0}        
};

extern "C" DLL_PUBLIC strus::TraceModule entryPoint;

strus::TraceModule entryPoint( tracelogger);

If we build this module and repeat our previous strusCreate method call with this tracelogger selected:

strusDestroy -s path=storage
strusCreate -T "log=traceexample" \
    -M .  -m modstrus_trace_example \
    -s "path=storage; metadata=doclen UINT16"

we get:

storage successfully created.
Database::Destructor called 1 times
Database::createClient called 1 times
Database::createDatabase called 1 times
Database::getConfigParameters called 1 times
DatabaseClient::Destructor called 1 times
DatabaseClient::createTransaction called 1 times
DatabaseTransaction::Destructor called 1 times
DatabaseTransaction::commit called 1 times
DatabaseTransaction::write called 8 times
Storage::Destructor called 1 times
Storage::createStorage called 1 times
Storage::getConfigParameters called 1 times
StorageObjectBuilder::Destructor called 1 times
StorageObjectBuilder::getDatabase called 1 times
StorageObjectBuilder::getStorage called 1 times

Resume

Thanks to the very restrictive design patterns used in Strus, it is possible to create and implement a proxy universe of the interfaces. This makes things like tracing and RPC in Strus as aspect on its own possible. In this article, we showed how to use call traces in Strus. We hope that the availability of tracing will raise the level of trust and bring more users to Strus. For reading more about Strus, have a look at my other articles about Strus.