Function Tracing

Function tracing

This page describes how to use Logme function tracing macros for logging function entry, function exit, arguments, return values, execution time and channel selection.

The examples below are based on the function tracing article and use the same API patterns.

---

Basic profiling macros

Function tracing in logme is implemented through the LogmeP family of macros.

Naming rules:

• V means the function is traced without logging a return value
• level suffixes:
  • D — Debug
  • I — Info
  • W — Warning
  • E — Error
  • C — Critical

If no level is specified, Info is used by default.

To log function entry and exit without parameters or return value, use:

LogmePV(); // or LogmePVI()

---

Example: basic function tracing

#include <thread>
#include <chrono>

#include <Logme/Logme.h>

int MyProc(int i, const char* name)
{
  LogmePV();

  std::this_thread::sleep_for(std::chrono::milliseconds(100));
  return i + 1;
}

int main()
{
  MyProc(123, "abc");
  return 0;
}

Typical output:

>> MyProc()
<< MyProc()

---

Measuring execution time

To include execution time in the output, enable the Duration flag on the logging channel:

int main()
{
  auto ch = Logme::Instance->GetDefaultChannelPtr();
  auto flags = ch->GetFlags();
  flags.Duration = true;
  ch->SetFlags(flags);

  MyProc(123, "abc");
  return 0;
}

Typical output:

>> MyProc()
<< MyProc() [102ms]

---

Logging return values

To log the return value, use a macro without the V suffix and pass a variable that stores the result:

int MyProc(int i, const char* name)
{
  int ret{};
  LogmePW(ret);

  ret = i + 1;

  std::this_thread::sleep_for(std::chrono::milliseconds(100));
  return ret;
}

Typical output:

>> MyProc()
<< MyProc() 124 [102ms]

---

Logging function arguments

To include function arguments in the log, pass them using helper macros.

Values only

int MyProc(int i, const char* name)
{
  LogmePV(ARGS(i, name));

  std::this_thread::sleep_for(std::chrono::milliseconds(100));
  return i + 1;
}

Typical output:

>> MyProc() 123, abc
<< MyProc()

Names and values

int MyProc(int i, const char* name)
{
  LogmePV(ARGS2(i, name));

  std::this_thread::sleep_for(std::chrono::milliseconds(100));
  return i + 1;
}

Typical output:

>> MyProc() i=123, name=abc
<< MyProc()

Macros such as ARGS1, ARGS2, and similar variants control how many parameters are passed and allow logme to include both values and names.

---

Custom printers for complex types

For standard types, logme already provides built-in formatting. For user-defined types, define a formatter:

struct Point
{
  int X;
  int Y;
};

template<> std::string FormatValue<Point>(const Point& value)
{
  return "Point(" + std::to_string(value.X) + ", " + std::to_string(value.Y) + ")";
}
static Point MakePoint(int x, int y)
{
  Point r{ x, y };
  LogmeP(r);

  return r;
}

This allows logme to print a meaningful representation of the custom type.

---

Selecting a logging channel

All previous examples use the default logging channel. To use a custom channel:

Logme::ID CHT{ "test" };

int MyProc(int i, const char* name)
{
  int ret{};
  LogmePI(ret, CHT, ARGS2(i, name));

  ret = i + 1;
  std::this_thread::sleep_for(std::chrono::milliseconds(100));

  return ret;
}

int main()
{
  auto ch = Logme::Instance->CreateChannel(CHT);
  ch->AddLink(::CH);
  MyProc(123, "abc");
  return 0;
}

Using a separate channel for function tracing is useful when this information is needed only occasionally.

A typical setup is to route tracing into a dedicated channel that is disabled by default, or is not created at all in the normal configuration. When deeper diagnostics become necessary, this channel can be created, enabled or unblocked, and function tracing starts producing output without changing the traced code itself.

This makes function tracing suitable for temporary investigation of control flow, unexpected latency, or difficult-to-reproduce bugs, while keeping normal logs smaller and quieter.

---

Output format

Typical output uses the following conventions:

• function entry:

>> Foo()

• function exit:

<< Foo()

• with execution time:

<< Foo() [102ms]

• with return value:

<< Foo() 124 [102ms]

• arguments without names:

>> Foo() 123, abc

• arguments with names:

>> Foo() i=123, name=abc

---

Notes

• Use the LogmeP macro family for function tracing.
• Use LogmePV when no return value needs to be logged.
• Use LogmeP... without V when you want to log the return value through a result variable.
• Enable the Duration flag on the channel when execution time is needed.
• Use ARGS(...) for values and ARGS2(...) for names and values.