Locust — partial results and ZeroMQ logs collector

In this article:

  • I’ll show you how to store partial results (each request time) in Locust
  • I’ll describe my way to collect all logs (from all slaves) in one place (using ZeroMQ)

What Locust is (very short intro):

Locust is a system for load testing written in Python (https://locust.io/). It’s easy when you need to write a few simple tests with HTTP requests only.
It starts to be fun when you want to use a different protocol and write more complicated and complex tests.

I’ll assume you have a basic Python knowledge. If you don’t know Locust, please start with studying its documentation.

Let’s get started!

Disclaimer: this is my second article about extending Locust. Here’s the 1st one (about custom clients): https://medium.com/@piotrgrabuszyski/locust-custom-client-23e205f4611f

Quick explanation:

Unfortunately, Locust gives us no option to keep partial results (each request time). Collecting such times can be important for example when we want to show the number of requests in time function.

Locust doesn’t allow us to collect all logs and save it in one place (for example file on master node).

To handle this tasks I created a special logger and a simple application (which uses ZMQ) to collect logs and store them in one place. Here’s how I did this:

Basic “to file” logger:

Fortunately, we can easily store partial results to file or print them on screen.

Let’s start with a very simple locust file:

If you are a bit familiar with Locust, this code should be 100% understood for you. Let’s move on and add some basic logger which allows us to write logs to file:

As you see, at first we load basic logger (line 6). Basic configuration can be set using environment variables (lines 8–10). Log format and date format are set in lines 12–15. If the path to a log file is set, we create the new handler and add it to our basic logger (lines 17–28). In line 36 we use our logger to write a message to file.

Now, set environment variables, for example:

export HOST=pg
export LOCUST_LOG_FILE=./locust.log

Start test and we should see:

[2018–05–14 16:10:38,062] pg/INFO/locust_default_logger: Task started
[2018–05–14 16:10:42,371] pg/INFO/locust_default_logger: Task started
[2018–05–14 16:10:46,671] pg/INFO/locust_default_logger: Task started

on a default output and such log:

{“time”:”2018–05–14T16:10:35.587Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:Task started}
{“time”:”2018–05–14T16:10:38.062Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:Task started}
{“time”:”2018–05–14T16:10:42.371Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:Task started}

in a file.

As you see, this is only a task-start time. We still need some more info.

Partial times:

To get times of particular requests we need to use Locust’s events mechanism.

In the example above we created 2 new functions and add them to Locust’s events. Locust now will call this functions every time when requests are ended (with success or failure).

Both functions must take arguments: request_type, name, response_time, response_length/exception and **kwargs.

The function which handles success should take response_length argument, and the one which handles failure should take exception argument.

**kwargs is optional but can save us some work much later, if Locust’s API will change and it will try to put some additional arguments to our function.

Now we should see such log:

{“time”:”2018–05–14T17:16:55.844Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:{“class”:”request”, “request_type”:”GET”, “name”:”/”, “result”:”success”, “response_time”:4, “response_length”:12267, “other”:{}}}
{“time”:”2018–05–14T17:16:59.808Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:{“class”:”request”, “request_type”:”GET”, “name”:”/”, “result”:”success”, “response_time”:3, “response_length”:12267, “other”:{}}}
{“time”:”2018–05–14T17:17:02.294Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:{“class”:”request”, “request_type”:”GET”, “name”:”/there_is_no_such_endpoint”, “result”:”error”, “response_time”:3, “exception”:”404 Client Error: NOT FOUND for url: http://127.0.0.1:8089/there_is_no_such_endpoint", “other”:{}}}
{“time”:”2018–05–14T17:17:06.113Z”, “loglevel”:”INFO”, “hostname”:”pg”, “message”:{“class”:”request”, “request_type”:”GET”, “name”:”/there_is_no_such_endpoint”, “result”:”error”, “response_time”:4, “exception”:”404 Client Error: NOT FOUND for url: http://127.0.0.1:8089/there_is_no_such_endpoint", “other”:{}}}

Now, we have each request end time (‘time’), its response length (‘response_length’) and time (‘response_time’), so we can aggregate it in every second, minute or just keep it this way and compare with other collected parameters like CPU or memory usage in context of time.

All logs in one place:

This is not the end of the journey. Logs from all slaves in one place — that’s our destination.

To achieve this we need to decide how to send logs via a network. We can use some kind of REST API, publish-subscribe system like Apache Kafka, the messaging system like MQTT, or just ZeroMQ (project’s web-page: http://zeromq.org/).

I’ve chosen the last option, because:

  • Locust uses ZMQ to synchronize slaves and send results, so libs should be already installed,
  • ZeroMQ does not require any additional component like broker,
  • ZMQ’s pipeline is exactly what we need here 😃
source: http://zguide.zeromq.org/page:all

Unfortunately, there’s also one issue with it — but in our case it’s not so important. There might be a problem with the communicates order. What I mean by that is — not always requests made to the attacked system will occur in the same order in our sink.

I’m writing about this because sometimes we need exact order — then this solution is not for you. It would be better to use e.x. Kafka for such purpose.

In our case however it’s not so important —we know that every test is different and we always need to assume some small measurement errors. For us most important is to register all requests.

The diagram above illustrates exactly how our system should work. Each slave (worker) should rapport each request to the master (sink). “Sink” could be built into Locust’s master, but in our case, it would be faster and more convenient if we start the dedicated app.

ZeroMQ sink:

At first — install ZMQ lib: http://zeromq.org/bindings:python

Let’s prepare a sink. It should receive all messages and store it to a file:

Great! The sink is ready! Set ZMQ_SINK_LOG_FILE variable and start the script.

Now teach Locust how to send messages to it:

As you can see, we created a new class which inherits from the logger.Handler class and “knows” what to do to log to ZMQ sink (emit method). Then we created handler using our new class and add it to default logger.

This is it ❗️ 😃

Summary:

At first — you should do it better I did in the example above. What I mean is you should divide the code into few files. I did it in one file is to clearly show the difference between them and to keep everything clean in my Gist.

Second — the performance. You need to keep in mind that sending additional information can slow down both network and processor. In addition — the handler we created above will block the thread until the message is sent, so if you cannot stop it — check this out: https://docs.python.org/3/howto/logging-cookbook.html#dealing-with-handlers-that-block

Third — there are other options to send logs via a network. Some are even “built into” Python’s logger (https://docs.python.org/2/library/logging.handlers.html). You need to use the solution the best for you, but creating our own ZMQ sink and logger is both fun and instructive.