Day 18: What is my concurrent or parallel Raku program doing?

Raku makes it easy to introduce a bit of parallelism into a program – at least, when the solution lends itself to that. Its asynchronous programming capabilities also shine when building concurrent applications. During the last year, I’ve enjoyed employing both of these in my work.

However, I also discovered that something was missing. It was relatively straightforward to build the parallel and concurrent things that I wanted in Raku. However, once they were built, I found it hard to reason about what they were doing. For example:

• For data parallel operations, what degree of parallelism was being achieved?
• What tasks executed in parallel, and were there missed opportunities for further task parallelism?
• Where was time being spent in different stages of an asynchronous workflow? For example, if a HTTP request could trigger background work, which later led to a message being sent over a WebSocket, where did the time go between these steps?
• Given a Cro web application is also an asynchronous pipeline, where is time going on request processing? Is some piece of middleware surprisingly eating up a lot of time?

At first, I started putting in bits of timing code that wrote results out to the console. Of course, I either had to remove it again afterwards, or guard it with an environment variable if I wanted to keep it in the code. And even then, the data it produced was quite hard to interpret. This all felt rather inefficient.

Thus, Log::Timeline was born. Using it, I learned a lot about my application’s behavior. Best of all, I didn’t just get answers to the questions I had, but also some that I hadn’t even considered asking. In this advent post, I’ll show how you can use this module also.

Trying it out

The first way we might make use of Log::Timeline doesn’t actually involve using the module at all, but rather using some library that already uses it to do logging. Since Cro::HTTP has done this (since 0.8.1), we can get our very first glimpse at Log::Timeline in action by building a Cro HTTP application.

Aside from something that produces log events, we also need some way to view the logs. At present, there are two modes of Log::Timeline output: writing a file in JSONLines format or sending them over a socket. The second of these is used by the log viewer in Comma (a Raku IDE), meaning that we can view the output live as our application runs.

Thus, assuming we already installed Cro, we can:

1. Create a new Cro Web Application project in Comma (works much like using cro stub at the command line)
2. Create a “Cro Service” Run Configuration (choose Edit Configurations on the Run menu)
3. On the Run Menu, choose “Run ‘service.p6’ and show Timeline”

The service will start up, and display the URL it is running at in the console (probably http://localhost:20000). If we make a request to it, then flip to the Timeline tab, we’ll see the request logged (in fact, do it in a browser then probably two requests are logged, since a favicon.ico is automatically requested). The requests can be expanded to see how the processing time within them is spent.

Cro can process requests to HTTP application in parallel. In fact, it’s both concurrent (thanks to use of asynchronous I/O) and parallel (all steps of request processing are run on the Raku thread pool). So, if we use the Apache Benchmark program to send 100 requests, 3 at a time, we’d hope to see an indication that up to 3 requests were being processed in parallel. Here’s the command:

ab -n 100 -c 3 http://localhost:20000/

And we do, indeed, see the parallelism:

Similarly, if we jack it up to 10 concurrent requests:

ab -n 100 -c 10 http://localhost:20000/

Then we will see something like this:

Looking a little more closely, we see that the “Process Request” task is logged as part of the HTTP Server category of the Cro module. However, that’s not all: tasks (things that happen over a period of time) can also have data logged with them. For example, the HTTP request method and target are logged too:

We might also notice that requests are displayed in alternating shades of color; this is to allow us to differentiate two tasks if they occur “back to back” with no time between them (or at least, none visible at our zoom level).

Adding Log::Timeline support to an application

What if we want to add Log::Timeline support to our own an application, so we can understand more about its behavior? To illustrate this, let’s add it to jsonHound. This is an application that looks through JSON files, and ensures that they are in compliance with a set of rules (its was built for checking the security of router configurations, but in principle could be used for much more).

When jsonHound is run, there are two steps:

1. Loading the rules, which are written in Raku
2. Checking each specified JSON file against the rules; if there is more than one file, they will be checked in parallel

We’ll create a Log::Timeline task for each of these. They go into a JsonHound::LogTimelineSchema module. The code in the module looks like this:

unit module JsonHound::Logging;

use Log::Timeline;

class LoadRules does Log::Timeline::Task["jsonHound", "Run", "Load Rules"] {
}

class CheckFile does Log::Timeline::Task["jsonHound", "Run", "Check File"] {
}

First, we use the Log::Timeline module. Then we create a class for each task that does the Log::Timeline::Task role (there is also an Event role, which can be used to log events that happen at a particular moment in time).

Next, we need to modify the program to use them. First, in the code that we want to add logging to, we need to use our task schema:

use JsonHound::LogTimelineSchema;

And now we can go to work. Loading the ruleset looks like this:

my $*JSON-HOUND-RULESET = JsonHound::RuleSet.new;
my $rule-file = $validations.IO;
CompUnit::RepositoryRegistry.use-repository:
        CompUnit::RepositoryRegistry.repository-for-spec(
                $rule-file.parent.absolute);
require "$rule-file.basename()";

We wrap it up as follows:

JsonHound::Logging::LoadRules.log: {
    my $rule-file = $validations.IO;
    CompUnit::RepositoryRegistry.use-repository:
            CompUnit::RepositoryRegistry.repository-for-spec(
                    $rule-file.parent.absolute);
    require "$rule-file.basename()";
}

When we’re not running with any logging output, the block is just executed as normal. If, however, we were to have the socket output, then it would send a message out over the socket when the block’s execution begins, and another when it ends.

The per-file analysis looks like this:

.($reporter-object) for @json-files.race(:1batch).map: -> $file {
    # Analysis code here
}

That is, we take the JSON files, and then map over them in parallel. Each produces a result, which we then invoke with the reporter. The exact details matter little; all we really need to do is wrap the analysis in our task:

.($reporter-object) for @json-files.race(:1batch).map: -> $file {
    JsonHound::Logging::CheckFile.log: {
        # Analysis code here
    }
}

Handily, the log method passes along the return value of the block.

What we’ve done so far will work, but we can go one step better. If we look at the log output, we might see a JSON input file that takes a long time to process, but we’d not know which one it is. We can annotate the log entry with whatever data we choose, simply by passing named arguments.

.($reporter-object) for @json-files.race(:1batch).map: -> $file {
    JsonHound::Logging::CheckFile.log: :$file, {
        # Analysis code here
    }
}

And with that, we’re ready! After adding a run configuration in Comma, and running it with the timeline viewer, we get a chart like this:

The future

While Log::Timeline can already offer some interesting insights, there’s still plenty more functionality to come. Current work in progress uses a new MoarVM API to subscribe to GC events and log them. This means it will be possible to visualize when GC runs and how much time is spent in it – and to correlate it with other events that are taking place.

I’m also interested in exposing various Rakudo-level events that could be interesting to see plotted on the timeline. For example, it would be possible to provide information on lock waiting times, or await times, or Supply contention times. Other ideas are plotting the times files or other resources are opened and closed, which may in turn help spot resource leaks.

Of course, just because there may be a wide range of things we could log does not mean they are all useful, and logging carries its own overhead. The use of the LogTimelineSchema naming convention looks forward to a further feature: being able to introspect the full set of events and tasks available. In Comma, we’ll then provide a UI to select them.

In closing…

No small amount of the time we spend solving problems with our programs goes on finding out what happens as they run. Good tooling can provide a window into the program’s behavior, and in some cases point out things that we might not even have considered. Log::Timeline is a pretty small module, and the visualizer didn’t take terribly long to implement either. However, the payback in terms of useful information makes it one of the most worthwhile thing I’ve built this year. I hope you might find it useful too.