locking occurs too high up in the call stack

[macdabby]

I am load testing a service under high concurrency and found some serious lag due to the locking feature of the logger.

Problem
using jaeger i was able to identify that some writes were being locked by up to 800ms per write at 40k logs per second.

Disabling lock
i tried disabling locking and saw lock delay completely eliminated, and writes that took 800ms were now clocked in microseconds. however, i understand that two concurrent writes might mix their output.

Moving the lock to the writer
digging a little deeper i noticed that the locking was likely applied too high in the stack. i ran an experiment replacing the stdio writer with a locking stdio writer. in my particular application it doubled the throughput of the application. the problem appears to be that the locking encompasses things like hooks and formatting which don't need to be locked. i could easily have multiple goroutines formatting their logs and encoding their json without any concurrency issues.

Fix
While I had to wrap the stdio writer to add locking at the write level outside the package, this could easily be done by moving the locking from the current location to the write() function within the logrus package. alternatively there could be a locked stdio writer which could be optionally set when disabling the main locking mechanism.

[dgsb]

I need to check back the code, but IIRC that's not so simple.
We need to lock the access to entry while calling the hook chain to prevent concurrent access to the map which holds the field stored in that entry.

[macdabby]

Interesting. In all of my microservices, there are no entries that would be used by more than one concurrent process. (I can't imagine a scenario where anyone would do that) so it wouldn't be an issue for us and disabling locking at that level has no impact. Maybe there could be two levels of locking so that it could be disabled at the entry but left enabled at the writer.

[dgsb]

I agree it doesn't make sense to use a Logger level mutex to protect Entry level resources.

[dgsb]

As a side effect it should be fixed by #1229, let me know if that improves things

[dgsb]

ping @macdabby can you try the last version to see if that improves things ?

[avenkatasubbaraya]

We're facing what looks like the same issue in our load tests. We tried v1.8.1 as well.

[github-actions]

This issue is stale because it has been open for 30 days with no activity.

[github-actions]

This issue was closed because it has been inactive for 14 days since being marked as stale.