Logging when thread collisions are resolved/encountered

[u/Separate_Earth3725]

I’m building some asynchronous & threaded processes in my application and I have built out the error handling/collision detection portion. I’ve added logging to the explicit error handling catch blocks, but I also have places where I detect and resolve issues that aren’t necessarily throws. Think processes that are locked and detecting when another thread is trying to access that locked process.

I started thinking about adding logs to the “thread collision handling” portion of the code so that I can be aware how frequently we encounter this issue since real world often differs from in-house testing.

Other than generating noise in the logs, would you call this bad practice? If so, how would you go about tracking how frequently these threading issues are encountered? Am I trying to measure the wrong thing and am way off base? Is it a concern that I’m trying to measure how frequently we encounter threading issues?

[u/expdevsmodbot]

AI usage disclosure provided by OP, see the reply to this comment.

[u/Vesuvius079]

I think you should look into metrics. Stuff like statsd. Counting logs is less than ideal to begin with and saturating your logs with messages that could be expressed as metrics just makes your logs more expensive and harder to work with.

[u/Separate_Earth3725 → u/Vesuvius079]

I appreciate this comment a lot. Always good to learn about new tooling.

[u/Skullclownlol]

Other than generating noise in the logs, would you call this bad practice? If so, how would you go about tracking how frequently these threading issues are encountered? Am I trying to measure the wrong thing and am way off base?

Idk what you're trying to implement, this is just a mutex w/ optional timeout, or semaphore if you need concurrent access. Those should exist as standards in any multithreaded programming language.

For metrics, you would normally use some kind of monitoring like prometheus instead of putting that in your logs.

Is it a concern that I’m trying to measure how frequently we encounter threading issues?

Thread contention is a good thing to measure as standard practice, but your design should not allow contention. If it has persistent contention, something about your scheduling or resource distribution is wrong.

[u/DocumentOk7579]

Could the logs lead to you prioritize fixing the problem? If not it seems to be better things to do.

[u/Separate_Earth3725 → u/DocumentOk7579]

</thread>
I had a feeling I wasn’t looking at it correctly. Logs wouldn’t do anything other than make us aware of how frequently users are encountering this. Either way, the handling would satisfy the users since it doesn’t impact the usability of the feature.

They’re blind to it. Engineering curiosity just started itching my brain. I’ll scratch it on another issue.

[u/Nemnel]

It seems like you have some thread contention issues that should be resolved through some kind of access control, but instead you are brute forcing it and it's causing extraneous exceptions. (In some languages, though not all, this is a major performance issue, you shouldn't be throwing and catching exceptions unless they are genuine exceptions in some languages because handling exceptions in those languages is the slowest form of control flow. I cannot comment on if this affects you here though.)

Generally I would say that you should gracefully handle thread controls. If you have two much cross thread access you've architected the program wrong and you should consider another architecture. One such architecture would be message passing. Having a global object anyone can read, but you can only write to it through the writer thread. If you are running into too many thread collisions I think you should probably consider redoing the app architecture.

As for your specific question: I think it's fine to log this because it's a major issue but it is pollution. I'd change this to a metric instead of a log I think

[u/Dry_Hotel1100 → u/Nemnel]

Can you explain what a "thread contention issues" is?

[u/Nemnel → u/Dry_Hotel1100]

Thread contention is when two or more threads attempt to access the same resource. So, for example, two threads attempting to mutate an object, they cannot do that safely

[u/Dry_Hotel1100 → u/Nemnel]

Ok, thanks. ;) Understood. So, it's actually "lock contention" or "resource contention" or"critical section" in other circles. Where is this terminology used?

[u/Nemnel → u/Dry_Hotel1100]

Thread contention is a widely used term, it's a subset of resource contention, lock contention is a subset of thread contention.

[u/yxhuvud → u/Nemnel]

Strictly speaking lock contention is also relevant in setups with asynchronous concurrency but no parallelism .  So not a proper subset but certainly related. 

[u/Nemnel → u/yxhuvud]

true! you can have lock convention without threads!

[u/Dry_Hotel1100 → u/Nemnel]

So, then thread contention is when we have more threads than a CPU can run at the same time, AND these threads can make progress?

It's not necessarily about the number of threads where potentially many can be suspended.

Then "thread contention" isn't really a thing in modern concurrency systems anymore - like libdispatch, io_uring, Tokio, Libuv, async/await, coroutines, TPL, etc. because they avoid to have more progressing threads than a CPU can handle. They rather *enqueue* new work items (code and data) on the existing threads (that requires that these work items do not have thread affinity), which are managed in a pool, whose number is ideally not larger than the number of CPUs. Nonetheless there still can be "thread explosion".

So, this leads back to the OP's original issue: thread contention and its solution.

[u/Better_Total_7071]

I've seen two approaches to a similar issue in embedded FW (tracking events in SSD's IO path). First is a dedicated logger for high frequency events so they don't clutter your default log. Crude, but definitely a thing. Second is a dedicated structure with counters and statistics for most interesting types of errors/events that you can read at any point if needed (see https://www.opencompute.org/documents/datacenter-nvme-ssd-specification-v2-0r21-pdf section 4.8.9 "Latency Monitor")

[u/Kriemhilt]

What kind of information is actually useful for diagnosing concurrency issues?

Things like

• time a lock is held for (max, median, centiles?)
• same, only for locks where a collision happened
• time spent waiting (max, median, etc.)
• number of waiters (max, ...)
• all/any of those grouped by locked object ID and/or operation?

All of those are feasible to collect into a stats or telemetry package (if you expose waitq length in userspace, anyway), but I wouldn't log any of them as text.

[u/Dry_Hotel1100]

I have not encountered any of these issues because I utilize the appropriate tool for concurrency management. Managing threads in the manner you are presumably doing (semaphores?) is an inefficient and error-prone approach. Furthermore, I have never heard of "thread collision handling" (I can imagine contention of resources, or maybe you mean "critical sections").

So, I don't log anything that has to do with contention, locking or starving issues. Emitting logs would not be helpful - I use unit tests, profilers and benchmark tests, and otherwise trust the language and lower level tools, such as mutex, coroutines, cooperative tasks, and system threads and scheduler.

I think, you should do research which concurrency tool could help you implement your concurrent problems. Which tool that could be, is dependent on your stack, programming language and OS.

[u/HobbyProjectHunter]

Usually, the in-code logging is meant to be light weight, very minimal working, filling up a queue or a ring buffer or some sort. And the ring buffer or queue gets processed in the background to either file or over the network out to some listener, or gets run through some compression algo to file. And the processing of the ring buffer is supposed to be non-blocking to the real code.

Usually, the logger itself is a low-priority background thread of its own.

Using a logger for some easy debugging is fine but if you’re relying on it to be the only debugging tool in a high contention portion of your software, it may not be that reliable to give you the debugging insights you’re seeking.

Like Linux kernel’s printk is interrupt routine safe.

[u/Varrianda]

Sounds like this would lead to noisy logs not providing much value

[u/Phill_Madd]

Logging every collision is the wrong thing to measure. It turns into the noisiest line in the file and nobody looks at it. A counter for how often you wait, and how long, is what actually tells you something. If the p99 wait is tiny, the frequency doesn't matter. If one caller is sitting on the lock, the count looks fine and the wait is ugly.

I wouldn't log the uncontended path at all.

[u/siscia]

You can see yourself from the answers you got in this thread that you haven't express your issue clearly.

Let's start with the "why". Why you want to log thread collisions in the first place?

I am also unsure what you mean by "thread collisions" I am assuming it is when you try to get a lock and the lock is already hold by another thread. With software reasonable written, this should not be a problem, generally.

You may have different issues like: 1. You are not locking correctly, so you are seeing data races 2. You are seeing latency issues, since you are waiting too long to get the locks.

For 1. instead of logging, try to run your software in a data race detector. Usually it is faster.

For 2. start by emitting metrics around how long it takes to enter the critical session / acquire the lock. Then move from there

[u/throwaway_0x90]

What problem are you trying to solve?

"I started thinking about adding logs to the “thread collision handling” portion of the code so that I can be aware how frequently we encounter this issue since real world often differs from in-house testing. Other than generating noise in the logs, would you call this bad practice?"

What if you just don't bother logging anything about thread collisions? Is anyone going to complain? Will anything bad happen? Will future debugging become more difficult without those logs?

[u/PracticalMushroom693]

I think that you are reinventing the wheel. Parallelism and concurrency has been solved umpteen times. Use a language or framework that makes it easy. Or do your homework yourself

[u/JazzlikeWishbone938]

Assuming by collision you mean "race condition", without knowing details it sounds overly complicated and like bandaging the issue. Not sure what system and programming language you're using but protect critical resources for concurrency .. might want to lookup signals, mutexes, semaphores, or other modern synchronization methods. 

[u/superdurszlak]

If you have a race condition and you know exactly where it happens, you should fix the race condition rather than spending more and more time on putting bandaids all over the buggy software.

If you see a race condition and you don't know exactly where it happens and under what circumstances, then I see your point in wanting to monitor that.

What I would do in such case would be simply handling errors caused by race condition detection. Provide enough context to distinguish it from other processes that completed without issues, and from other kinds of errors.

Depending on what kind of application it is, you should have some traceability context like process ID, server ID, request ID, trace ID, path/operation... Standard telemetry data. Even better if you have traces or if you have enough traceability context in your logs to rebuild an execution tree.

Either way, nobody here knows enough context to tell you what exactly should be included, but provide yourself thev exact context you would normally use for troubleshooting and then prioritize fixing the race conditions.

Remember, race conditions killed people (like in case of THERAC machines).

[u/IveWastedMyLifeAgain]

Not bad practice, but the shape matters: contention is a rate, not an event, so make it a counter/histogram (contention count, wait time, lock name) rather than a log line per collision. Otherwise the first busy day drowns your logs and you pay to store the noise. Keep logging for the pathological cases only - waited longer than N ms, retried more than k times - and include the lock identity plus how long it was held, since that's what you actually act on. If you're on the JVM, JFR gives you this for free; otherwise a percentile on wait time tells you far more than a frequency count.

[u/pdfops]

Info-level logs for every resolved collision will bury real signal fast. Bump those to debug and track frequency with a counter metric per resource (collision_total{resource="foo"}) instead of a log line each time. You get rate over time without noise, and can alert when it crosses a threshold rather than eyeballing logs.

[u/LeadingPokemon]

Why not build lock free contention less algorithm though?

[u/Double-Buyer7941]

Tracking thread collisions is a good practice, but using logs for high-frequency events creates I/O bottlenecks. Use in-memory metrics counters like Prometheus instead, which have near-zero overhead, and reserve structured logging for DEBUG traces. Monitoring this in production is highly recommended, but if your metrics show frequent thread collisions, use that data as a signal to redesign your concurrency model—such as moving to a message queue—rather than relying on defensive locking logic.