Multi-threaded performance on ARM (Nvidia Xavier)

[t-wiser]

Where I work we use a custom logging framework that I am trying to replace. I've been evaluating mainly boost.log and spdlog along with our custom logger and some small variations on it. Part of the evaluation is a benchmark that simply logs 1,000,000 messages as quickly as possible to a file using anywhere from 1 to 8 threads. By doing this I'm trying to get an idea of worst case performance with heavy contention on the logger.

The performance of all loggers on X86 architecture follows a general asymptotic pattern of the total execution time decreasing every time you add a thread. Going from 1 thread to 2 threads has a relatively large decrease in time. Going from 7 threads to 8 threads has a relatively small decrease in time, but it is still generally there. It's easy to see the trend that eventually the decrease in run time levels off and likely may even start increasing with too much contention.

All of that was as expected, but then I tried to repeat the experiment on the ARM architecture using an Nvidia Xavier, which has 8 cores and 32GB of RAM. All loggers except for spdlog continue to show the same asymptotic pattern of decreasing total run time. spdlog instead seems to exhibit an increasing asymptotic run time pattern. Is this multi-threaded performance a known problem on ARM? spdlog is my preferred logger and I wanted to push us in that direction, but the ARM performance is worrying me. Our applications are heavily multi-threaded and need to run on both architectures.

Here are some details that may help.

The code I'm running basically boils down to the following.

// Setup logger
auto logger = spdlog::basic_logger_mt("logger name", "file name");
logger->set_level(spdlog::level::debug);
logger->set_pattern("[%l] [%Y-%m-%d %H:%M:%S.%e] [%t] [%!] %v");

// Later, divide number of messages equally by number of threads. Each thread then runs the following loop.
for (size_t i = 0; i < count; ++i) {
    SPDLOG_LOGGER_INFO(logger, "Iteration {}: {:.15f}", i, DBL); // DBL is some constant
}

Here is an example of the total run times for spdlog for the two architectures.

        Run Time (s)
Threads  X86    ARM
   1    3.189  1.951
   2    1.787  3.156
   3    1.548  3.281
   4    1.498  3.218
   5    1.441  4.085
   6    1.570  5.620
   7    1.635  5.615
   8    1.572  5.597

Thank you for your attention and for this great library. I love the speed, functionality and ease of use of spdlog and hope that I can use it at work. I'm hoping this performance problem on ARM is a fluke or something that I am doing wrong.

Edit I forgot to add that I'm testing with spdlog version 1.9.2.

[gabime]

Thank you for your attention and for this great library

Thanks for the nice feedback !

The performance of all loggers on X86 architecture follows a general asymptotic pattern of the total execution time decreasing every time you add a thread.

I am not sure about that, since they all write to same sink and stumble the same lock.

Another thing to check is the BUFSIZ of the libc your are using. If it is very small, lots of writing to disk would happen instead of buffering.
This can be controlled with setvbuf(..)

[t-wiser]

Thanks for the reply!

The performance of all loggers on X86 architecture follows a general asymptotic pattern of the total execution time decreasing every time you add a thread.

I am not sure about that, since they all write to same sink and stumble the same lock.

The lock contention isn't quite as bad as my initial posting makes it look, though it is still high. The actual loop that each thread runs looks like this:

for (size_t i = 0; i < count; ++i) {
    auto t1 = high_resolution_clock::now();
    SPDLOG_LOGGER_INFO(logger, "Iteration {}: {:.15f}", i, DBL); // DBL is some constant
    auto t2           = (high_resolution_clock::now() - t1);
    times[offset + i] = t2; // times is pre-allocated vector
}

Regardless, the patterns I mentioned are very repeatable and consistent. You can see the shape in the example results I provided.

Another thing to check is the BUFSIZ of the libc your are using. If it is very small, lots of writing to disk would happen instead of buffering. This can be controlled with setvbuf(..)

Thanks for the idea. It looks like on all the systems I've been testing, including the ARM machine, BUFSIZ is set to 8192. I'll try to experiment with different values and see how that affects things.

[t-wiser]

Another thing to check is the BUFSIZ of the libc your are using. If it is very small, lots of writing to disk would happen instead of buffering. This can be controlled with setvbuf(..)

Thanks for the idea. It looks like on all the systems I've been testing, including the ARM machine, BUFSIZ is set to 8192. I'll try to experiment with different values and see how that affects things.

It looks like the buffer size doesn't make a noticeable difference on my ARM test machine (I haven't checked on x86), even for a single threaded logger and a single thread. I tested with buffer sizes of all powers of two from 1KB to 1MB. I had to hack spdlog's source to add the ability to call setvbuf(...), but I did verify that it was changing the buffer size when requested.

I'm wondering if there is something about the memory model on ARM that makes mutex locking perform worse than on x86. If I can find some time, I might try to look into boost.log source to see if I can see if they are doing anything out of the ordinary for locking.

[gabime]

I might try to look into boost.log source to see if I can see if they are doing anything out of the ordinary for locking.

Lets us know if you find something we can do.

Also, I suggest using the bench/latency.cpp for accurate and reproducible results.

[t-wiser]

I might try to look into boost.log source to see if I can see if they are doing anything out of the ordinary for locking.

Lets us know if you find something we can do.

Will do.

Also, I suggest using the bench/latency.cpp for accurate and reproducible results.

I am unable to build latency.cpp on either x86 or ARM. It downloaded and built googlebench as part of the build. The errors I get on x86 (CentOS 7, gcc 4.8.5) are variations on the following.

/home/twiser/development/experimental/external/spdlog/bench/latency.cpp: In function ‘void bench_dev_null()’:
/home/twiser/development/experimental/external/spdlog/bench/latency.cpp:68:86: error: no matching function for call to ‘RegisterBenchmark(const char [13], void (&)(benchmark::State&, std::shared_ptr<spdlog::logger>), std::remove_reference<std::shared_ptr<spdlog::logger>&>::type)’
     benchmark::RegisterBenchmark("/dev/null_st", bench_logger, std::move(dev_null_st))->UseRealTime();
                                                                                      ^
/home/twiser/development/experimental/external/spdlog/bench/latency.cpp:68:86: note: candidates are:
In file included from /home/twiser/development/experimental/external/spdlog/bench/latency.cpp:10:0:
/home/twiser/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1040:29: note: benchmark::internal::Benchmark* benchmark::RegisterBenchmark(const char*, void (*)(benchmark::State&))
 inline internal::Benchmark* RegisterBenchmark(const char* name,
                             ^
/home/twiser/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1040:29: note:   candidate expects 2 arguments, 3 provided
/home/twiser/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1048:22: note: template<class Lambda> benchmark::internal::Benchmark* benchmark::RegisterBenchmark(const char*, Lambda&&)
 internal::Benchmark* RegisterBenchmark(const char* name, Lambda&& fn) {
                      ^
/home/twiser/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1048:22: note:   template argument deduction/substitution failed:
/home/twiser/development/experimental/external/spdlog/bench/latency.cpp:68:86: note:   candidate expects 2 arguments, 3 provided
     benchmark::RegisterBenchmark("/dev/null_st", bench_logger, std::move(dev_null_st))->UseRealTime();
                                                                                      ^

The errors I get on ARM (Ubuntu 18.04, gcc 7.5.0, x86 cross compiling for ARM) are variations of the following.

In file included from /home/devadmin/development/experimental/external/spdlog/bench/latency.cpp:10:0:
/home/devadmin/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h: In instantiation of ‘benchmark::RegisterBenchmark(const char*, Lambda&&, Args&& ...)::<lambda(benchmark::State&)> [with Lambda = void (&)(benchmark::State&, std::shared_ptr<spdlog::logger>); Args = {std::shared_ptr<spdlog::logger>}]’:
/home/devadmin/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1062:48:   required from ‘struct benchmark::RegisterBenchmark(const char*, Lambda&&, Args&& ...) [with Lambda = void (&)(benchmark::State&, std::shared_ptr<spdlog::logger>); Args = {std::shared_ptr<spdlog::logger>}]::<lambda(class benchmark::State&)>’
/home/devadmin/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1061:38:   required from ‘benchmark::internal::Benchmark* benchmark::RegisterBenchmark(const char*, Lambda&&, Args&& ...) [with Lambda = void (&)(benchmark::State&, std::shared_ptr<spdlog::logger>); Args = {std::shared_ptr<spdlog::logger>}]’
/home/devadmin/development/experimental/external/spdlog/bench/latency.cpp:68:86:   required from here
/home/devadmin/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1062:41: error: variable ‘fn’ has function type
       name, [=](benchmark::State& st) { fn(st, args...); });
                                         ^~
/home/devadmin/development/experimental/external/spdlog/build/_deps/googlebenchmark-src/src/../include/benchmark/benchmark.h:1062:41: error: variable ‘fn’ has function type

[t-wiser]

I might try to look into boost.log source to see if I can see if they are doing anything out of the ordinary for locking.

Lets us know if you find something we can do.

It looks like the way I've setup boost.log it is using a boost::recursive_mutex and then uses the lock, try_lock, or lock_shared functions to acquire the lock. That is just from a cursory glance at the code, which I'm not familiar with. I also haven't had the time to look into how boost::recursive_mutex is implemented. I wouldn't expect that boost implemented their mutex much differently than the standard library did, so maybe the locking isn't the issue.

[t-wiser]

I decided to run a quick experiment to test the std mutex vs boost recursive_mutex locking speed. Here are the basics of what I did.

launch 8 threads that each do the following:
  wait for a condition variable to wake them up
  initialize a local counter to zero
  for 1,000,000 times {
    lock a mutex
    increment the local counter
    unlock the mutex
  }
  store the local counter in a global array element reserved for the thread

sleep a brief time to allow all 8 threads to startup and enter their wait state
get the current (start) time
notify all threads to wake up
join all threads
get the current time and log the elapsed time since start

While I didn't expect the mutex implementations to vary wildly, I did expect the boost one to be slightly slower as it is a recursive mutex and thus needs to be slightly more complicated. Indeed, on x86, this was the case. The std mutex case generally took about 0.6 - 0.65 seconds to finish on my machine, while the boost recursive mutex case generally took about 0.76 - 0.8 seconds to finish.

The same test on my ARM machine, however, produced very different results. The std mutex case generally took about 4.6 - 6.4 seconds to finish while the boost recursive mutex case generally took about 1.6 - 5.3 seconds (but was always faster than std for each run). This seems to suggest two things. First, locking in general on ARM, at least on this particular machine, is about an order of magnitude slower than on (my) x86. Second, boost's recursive mutex (we're using version 1.66) has a much better implementation than the std mutex on the ARM platform we're using.

So I think I may have gone back to suspecting the locking as being the main culprit here.

[gabime]

Interesting results. Does the boost mutex use the same prhread impl underneath?

Related: https://stackoverflow.com/questions/19478925/why-is-boostmutex-faster-than-stdmutex-as-of-vs2013

[gabime]

Pr #1846 fixed this long time ago. Are you using an old version of spdlog?

[t-wiser]

I have been testing with version 1.9.2, but just tried with the head of v1.x branch. I still get the build errors. I can see that commit in the commit history though, so I'm not sure what's going on.