Replies: 4 comments 7 replies
-
|
As you say, clearly there is some instability here - the 20% -ve slowdown
for L3 logging is particularly weird. I suspect it has to do with time
keeping, e.g. NTP made the clock run slower.
I think we'll need to do multiple runs (8?) and take the median. I realise
that's painful, but I can't think of an alternative.
…On Thu, 13 Jun 2024 at 02:53, Aditya P. Gurajada ***@***.***> wrote:
HI, @gregthelaw <https://github.com/gregthelaw> --
I now have the test.sh and report generation productized under the 2
commits under PR #75 <#75> .
I ran a perf-test on AWS bare-metal instance with 72 cores.
Test configuration: 32-clients, 1Mil messages / client: Server: 1, 2, 4, 8
thread-count
Here are the post-processed results.
I was expecting to see increasing degradation due to concurrent threads
logging but the results don't reflect this behaviour.
Below each chunk of output, I have annotated my observations. Comments
welcome:
*Performance comparison for NumClients=32, NumOps=32000000 (32 Million),
NumThreads=1*
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Run-Type | Server throughput | Srv:Drop | Client throughput | Cli:Drop | NumOps/thread |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Baseline - No logging | ~295.85 K ops/sec | 0.00 % | ~9.79 K ops/sec | 0.00 % | 32 Million |
| L3-logging (no LOC) | ~355.17 K ops/sec | 20.05 % | ~11.83 K ops/sec | 20.85 % | 32 Million |
| L3-fast logging (no LOC) | ~296.56 K ops/sec | 0.24 % | ~9.73 K ops/sec | -0.58 % | 32 Million |
| L3-fprintf() logging (no LOC) | ~270.67 K ops/sec | -8.51 % | ~8.87 K ops/sec | -9.44 % | 32 Million |
| L3-write() logging (no LOC) | ~188.06 K ops/sec | -36.43 % | ~6.09 K ops/sec | -37.77 % | 32 Million |
| L3-logging default LOC | ~296.63 K ops/sec | 0.26 % | ~9.76 K ops/sec | -0.31 % | 32 Million |
| L3-logging LOC-ELF | ~297.14 K ops/sec | 0.44 % | ~9.77 K ops/sec | -0.19 % | 32 Million |
| spdlog-logging | ~284.75 K ops/sec | -3.75 % | ~9.36 K ops/sec | -4.36 % | 32 Million |
| spdlog-backtrace-logging | ~283.64 K ops/sec | -4.13 % | ~9.31 K ops/sec | -4.90 % | 32 Million |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
- L3-logging is 20% faster than baseline: This is totally unexpected
and unheard of. I attribute this to some m/c instability [?]
- The remaining numbers of %-drop are "in line" what we've been seeing
elsewhere.
*Performance comparison for NumClients=32, NumOps=32000000 (32 Million),
NumThreads=2*
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Run-Type | Server throughput | Srv:Drop | Client throughput | Cli:Drop | NumOps/thread |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Baseline - No logging | ~457.74 K ops/sec | 0.00 % | ~15.41 K ops/sec | 0.00 % | 16 Million |
| L3-logging (no LOC) | ~442.93 K ops/sec | -3.24 % | ~14.87 K ops/sec | -3.46 % | 16 Million |
| L3-fast logging (no LOC) | ~437.40 K ops/sec | -4.44 % | ~14.68 K ops/sec | -4.75 % | 16 Million |
| L3-fprintf() logging (no LOC) | ~451.28 K ops/sec | -1.41 % | ~15.31 K ops/sec | -0.62 % | 16 Million |
| L3-write() logging (no LOC) | ~238.83 K ops/sec | -47.82 % | ~7.75 K ops/sec | -49.70 % | 16 Million |
| L3-logging default LOC | ~439.79 K ops/sec | -3.92 % | ~14.76 K ops/sec | -4.20 % | 16 Million |
| L3-logging LOC-ELF | ~439.76 K ops/sec | -3.93 % | ~14.76 K ops/sec | -4.20 % | 16 Million |
| spdlog-logging | ~406.27 K ops/sec | -11.24 % | ~13.63 K ops/sec | -11.56 % | 16 Million |
| spdlog-backtrace-logging | ~457.64 K ops/sec | -0.02 % | ~15.63 K ops/sec | 1.43 % | 16 Million |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
- For 2-threads, the overall %-age drops are seemingly reasonable / as
expected.
- Between 1 and 2 server-threads, one would expect to see greater
degradation for fprintf() but it has gone down.
- write() perf has worsened - I guess this could be due to concurrent
threads logging [?]
*Performance comparison for NumClients=32, NumOps=32000000 (32 Million),
NumThreads=4*
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Run-Type | Server throughput | Srv:Drop | Client throughput | Cli:Drop | NumOps/thread |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Baseline - No logging | ~695.46 K ops/sec | 0.00 % | ~24.44 K ops/sec | 0.00 % | 8 Million |
| L3-logging (no LOC) | ~673.46 K ops/sec | -3.16 % | ~23.68 K ops/sec | -3.11 % | 8 Million |
| L3-fast logging (no LOC) | ~658.55 K ops/sec | -5.31 % | ~22.99 K ops/sec | -5.94 % | 8 Million |
| L3-fprintf() logging (no LOC) | ~580.25 K ops/sec | -16.57 % | ~19.95 K ops/sec | -18.35 % | 8 Million |
| L3-write() logging (no LOC) | ~314.35 K ops/sec | -54.80 % | ~10.34 K ops/sec | -57.69 % | 8 Million |
| L3-logging default LOC | ~681.19 K ops/sec | -2.05 % | ~23.89 K ops/sec | -2.24 % | 8 Million |
| L3-logging LOC-ELF | ~664.07 K ops/sec | -4.51 % | ~23.27 K ops/sec | -4.79 % | 8 Million |
| spdlog-logging | ~504.25 K ops/sec | -27.49 % | ~17.06 K ops/sec | -30.18 % | 8 Million |
| spdlog-backtrace-logging | ~626.13 K ops/sec | -9.97 % | ~21.84 K ops/sec | -10.62 % | 8 Million |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
- With 4 and, below, 8 threads, write() and spdlog logging performance
seems to go down quite a bit. This is consistent with the hypothesis that
concurrent logging degrades these schemes even more.
- But fprintf() degradation is fluctuating -- this may be due to
file-system / glibc caching?
-
*Performance comparison for NumClients=32, NumOps=32000000 (32 Million),
NumThreads=8*
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Run-Type | Server throughput | Srv:Drop | Client throughput | Cli:Drop | NumOps/thread |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
| Baseline - No logging | ~744.79 K ops/sec | 0.00 % | ~26.40 K ops/sec | 0.00 % | 4 Million |
| L3-logging (no LOC) | ~734.90 K ops/sec | -1.33 % | ~26.08 K ops/sec | -1.22 % | 4 Million |
| L3-fast logging (no LOC) | ~719.97 K ops/sec | -3.33 % | ~25.50 K ops/sec | -3.42 % | 4 Million |
| L3-fprintf() logging (no LOC) | ~681.84 K ops/sec | -8.45 % | ~23.86 K ops/sec | -9.61 % | 4 Million |
| L3-write() logging (no LOC) | ~293.85 K ops/sec | -60.55 % | ~9.63 K ops/sec | -63.51 % | 4 Million |
| L3-logging default LOC | ~720.68 K ops/sec | -3.24 % | ~25.44 K ops/sec | -3.66 % | 4 Million |
| L3-logging LOC-ELF | ~726.58 K ops/sec | -2.44 % | ~25.68 K ops/sec | -2.75 % | 4 Million |
| spdlog-logging | ~581.29 K ops/sec | -21.95 % | ~19.93 K ops/sec | -24.50 % | 4 Million |
| spdlog-backtrace-logging | ~758.00 K ops/sec | 1.77 % | ~27.20 K ops/sec | 3.01 % | 4 Million |
+-------------------------------+-------------------+----------+-------------------+----------+---------------+
*Summary Conclusions*:
- Overall, with increased concurrency other logging schemes show
greater degradation.
- We are not seeing the ~1% performance degradation with L3-logging.
It's always 3+%. Maybe a measurement anomaly [?]
- spdlog-backtrace logging is competitive with L3 and l3-fast logging,
in terms of degradation, but you cannot unpack the log-info post-the run.
(Backtrace only dumps while the server is running.)
- L3-fast logging still has some non-trivial degradation. You need to
investigate and address open issue #76
<#76>.
—
Reply to this email directly, view it on GitHub
<#79>, or unsubscribe
<https://github.com/notifications/unsubscribe-auth/ANHOS7EVS2L44EMCXQTGN5LZHDUO3AVCNFSM6AAAAABJHLUHUWVHI2DSMVQWIX3LMV43ERDJONRXK43TNFXW4OZWHAYTIMRZGY>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
--
https://undo.io | Record. Replay. Resolve.
Technical Paper: Fix Bugs Faster with Time Travel Debugging
<https://info.undo.io/time-travel-debugging-whitepaper>
|
Beta Was this translation helpful? Give feedback.
-
|
Email exchange with @gregthelaw on this comment: It's not a 20% drop but a 20% gain. L3-logging did -better- than baseline. That's even weird! Sorry that's what I meant by "negative slowdown" -- negative slowdown = speedup. It's clearly a measurement error. My guess is to do with clocks. e.g. NTP detected that the system clock was ahead, so it slowed down the clock for a bit and so the test appeared to get more throughput. If that's right, then doing a bunch and taking the median should solve it. Greg |
Beta Was this translation helpful? Give feedback.
-
|
All very odd, isn't it? The numthreads=1 and numthreads=4 are reasonable. numthreads=2 is disappointing because, as you say, spdlog appears to be competitive. But on numthreads=8 we once again see spdlog and L3 all have negative slowdown - i.e. a speedup compared to baseline. This implies that we are still not able to measure accurately. Did you say the machine you're using has 72 physical cores? That is presumably a NUMA architecture, and weird shit can indeed happen there. Can you try with a smaller machine, specifically one that is not NUMA? And/or we may need to experiment with pinning threads to CPU cores - e.g. |
Beta Was this translation helpful? Give feedback.
-
|
@gregthelaw I am using a c5n.metal h/w config. As per this AWS article, for the machine I am using: As per Intel's this processor arch doc, the Skylake Mesh Architecture does seem like it's a NUMA machine. This AWS EC2 doc gives details of cores and vCPUs. Scroll down to a section titled: "Compute optimized instances" I think the processor has 36 physical cores x2 hyper-threading for a total of 72 vCPUs. About your suggestions of trying diff machines: I am running out of time right now. Finding out a non-NUMA machine with sufficient large # of core counts so we can run with 16 or 32-clients, plus 4-threads ... means we need a non-NUMA machine with 20+ or 36+ cores. Chasing that down will take time. I need to start developing that preso. Let me make some progress on that first ... and if I have cycles, will try to hunt a machine down. |
Beta Was this translation helpful? Give feedback.
-
|
I experimented with my laptop. I carefully shut down all other programs, plugged in, and deliberately throttled CPUs to try to avoid weird thermal/throttling issues.There is some bizarre effect with spdlog and two threads: everything else looks vaguely sane. There are a few -ve slowdowns, but all under 1% so I think we conclude "no measurable difference if the change against baseline is < 1% either way." But spdlog multi-threaded is just weird: 4 and 8 threads are still less slowdown than 1, which makes no sense: there is a mutex, it will be always uncontended in the single threaded case. |
Beta Was this translation helpful? Give feedback.
-
|
@gregthelaw - For tomorrow, I am not particularly concerned about these variations. I need some info from you: I experimented with my laptop. Can you give me the specs of your Linux workstation. Machine, core description, # of threads etc ...? |
Beta Was this translation helpful? Give feedback.
-
|
Oh wait, hang on, it looks like maybe you need to configure spdlog differently for multithreaded. Do we do that? |
Beta Was this translation helpful? Give feedback.
-
|
Hmm, yeah, looks like we do: |
Beta Was this translation helpful? Give feedback.
-
|
Oh but hang on, the above line is only compiled if |
Beta Was this translation helpful? Give feedback.
-
|
@gregthelaw - I don't have time right now to dig into this spdlog interface angle. I built the spdlog code using examples from these links: https://github.com/gabime/spdlog https://github.com/gabime/spdlog#backtrace-support I built the L3 integration using sample code from here: https://github.com/gabime/spdlog/blob/v1.x/example/example.cpp Can you dig into those to see if I've made a mistake in my use of their interfaces? Thanks! |
Beta Was this translation helpful? Give feedback.
-
|
For spdlog-backtrace, there is no mention of multi-threading support in their examples. The usage seems to be just like: ... which is what I did. That's why you don't see any traces of I could stand corrected ... if you can dig into the details. |
Beta Was this translation helpful? Give feedback.
-
HI, @gregthelaw --
Updated 15.Jun.2024:
I now have a new commit under PR #85 that can be used to run multiple iterations of client-server performance tests.
I had to massage
perf-report.pyto find the median value of metrics and generate the comparison report.Here are the reports:
Perf run parameters: 32-clients, 1 Million msgs/client, run 5 iterations with different server-thread configurations
Observations:
write()logging and spdlog logging does go up.Performance comparison for For 32 clients, 32000000 (32 Million) msgs, num_threads=1
Performance comparison for For 32 clients, 32000000 (32 Million) msgs, num_threads=2
**** (Using median value of metric across 5 iterations) ****
Performance comparison for For 32 clients, 32000000 (32 Million) msgs, num_threads=4
**** (Using median value of metric across 5 iterations) ****
Performance comparison for For 32 clients, 32000000 (32 Million) msgs, num_threads=8
**** (Using median value of metric across 5 iterations) ****
I now have the
test.shand report generation productized under the 2 commits under PR #75 .I ran a perf-test on AWS bare-metal instance with 72 cores.
Test configuration: 32-clients, 1Mil messages / client: Server: 1, 2, 4, 8 thread-count
Here are the post-processed results.
I was expecting to see increasing degradation due to concurrent threads logging but the results don't reflect this behaviour.
Below each chunk of output, I have annotated my observations. Comments welcome:
Performance comparison for NumClients=32, NumOps=32000000 (32 Million), NumThreads=1
Performance comparison for NumClients=32, NumOps=32000000 (32 Million), NumThreads=2
fprintf()but it has gone down.write()perf has worsened - I guess this could be due to concurrent threads logging [?]Performance comparison for NumClients=32, NumOps=32000000 (32 Million), NumThreads=4
write()andspdloglogging performance seems to go down quite a bit. This is consistent with the hypothesis that concurrent logging degrades these schemes even more.fprintf()degradation is fluctuating -- this may be due to file-system / glibc caching?Performance comparison for NumClients=32, NumOps=32000000 (32 Million), NumThreads=8
Summary Conclusions:
spdlog-backtracelogging is competitive with L3 and l3-fast logging, in terms of degradation, but you cannot unpack the log-info post-the run. (Backtrace only dumps while the server is running.)L3-fastlogging still has some non-trivial degradation. You need to investigate and address open issue L3-Fast logging interface improvements. #76.Beta Was this translation helpful? Give feedback.
All reactions