-
Notifications
You must be signed in to change notification settings - Fork 32
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Should serialized-appender use a recursive lock? #21
Comments
I'm aware of this problem under a bit of a different angle, something like "(log:info (call-that-uses-logging-itself))" hangs trying to take appender lock recursively. I was planning to solve it, by making a change from "binary logging idea" issue, which would first compute all format arguments putting them into dynamic-extent vector, and then do the call. That would solve the above problem, but not your example. I think ideally it should behave as same as if the lock was not there (is like in single threaded built), which is same as recursive lock. Imho the debug-log-statements is an overkill. Current behavior is obviously broken, recursive lock makes it behave same as it there was no lock, which satisfies principle of least surprise. So unless you have objections, I'll just make recursive lock change (may have to wait until weekend) or I'll merge pull request for she same Jan Moringen notifications@github.com wrote:
|
Out of curiosity: on which implementation does this happen? At least in SBCL, attempting to re-acquire a non-recursive lock signals an error instead of hanging.
I think computing an intermediate value such as the formatted string outside the critical section and then writing it to the stream in the critical section would solve both problems. I wrote "intermediate value" because it may not be a formatted string for some kinds of appenders. This would also minimize the time spent in the critical section.
The solution in the previous paragraph seems better to me although it requires more effort to implement. Btw: I would really appreciate the binary logging idea for writing custom appenders. |
You are right about recursive lock on SBCL, gives an error instead of hanging now, maybe my memory is from other implementation? I assume you mean using Right now even if you have a lot of debug/trace statements, and setting root level to debug, the consing impact is still low (when not using pretty printer), because everything gets printed directly to the eventual stream. Seems weird to give that up and introduce consing into design just to solve a concurrency issue. What is the problem with recursive lock solution? I tested it and everything seems to work fine (handler-bind ((error (lambda (e)
(log:error "Got error" e)
(abort))))
(log:info "~d")
(log:info "After the error"))
;
; caught WARNING:
; Too few arguments (0) to FORMAT "~d": requires at least 1.
; See also:
; The ANSI Standard, Section 22.3.10.2
;
; compilation unit finished
; caught 1 WARNING condition
<ERROR> [08:03:42] [repl-thread] cl-user () -
Got error E: #<SB-FORMAT:FORMAT-ERROR {100E149383}>
; Evaluation aborted on #<SB-INT:FORMAT-TOO-FEW-ARGS-WARNING "Too few arguments (~D) to ~S ~S: requires at least ~D." {100DF7E613}>. |
Yes, at least for string-stream based appenders.
I see. My point was that running formatter code in the critical section may block other threads longer than just writing a precomputed value to the stream. However, as you pointed out, formatting directly to the target stream avoids consing.
I don't think there is any functional problem; the tradeoff is wrt. performance: less consing vs. smaller critical section. I'm not sure which one is more important. Apart from that, it would be cool if one could write appenders that just receive the "raw" logging data without formatters being involved. |
The "able to write appenders without formatting being involved" is exactly what binary logging wish list issue is about, it would introduce new type of appender that receives a vector of values being logged, to do with as it wishes, from maintaining of circular buffet of last 1000 debug messages to cl-storing it to binary log file, for future analysis with some tool Jan Moringen notifications@github.com wrote:
|
Has been addressed in sharplispers#8. |
Consider the following:
(log:info "~A")
is obviously wrong since there are not enough format arguments. One would expect this error to be caught and reported by the outer "catch-all"handler-bind
. However, since the format error is signaled while inappender-do-append
, the(log:error "caught error: ~A" condition)
code re-entersappender-do-append
and causes a recursive lock attempt. As a consequence, a relatively harmless format error in logging code escalates even beyond the intended "catch-all" error handling.I can imagine two possible improvements:
<INFO> [20:08:12] cl-user () - <<error printing log message>>
. This approach would similar to the usual<SOME-CLASS <<error printing object>> >
-behavior. This solution would not change the control flow, i.e. return:finished
in the above example, since no error would be signaled.This solution would change the control flow since the format-error would still be signaled.
*debug-log-statements?*
:)The text was updated successfully, but these errors were encountered: