Reading through this thread, I'm wondering if we should focus on improving identification of log lines in terms of where they come from and when they were generated, while keeping to go through the existing mechanism of sending messages back to main process for output (so that we don't need the mutex). If we sent timestamps & thread IDs along with the Debug() messages, one could later post-process debug.log to, get things sorted/split as desired.
This wouldn't support the use case of "millions of lines" very well, but I'm not convinced that's what we should be designing this for. A mutex becomes potentially problematic at that volume as well, and it also seems like a rare use case to begin with. In cases where it's really needed, a local patch to get logs into files directly (as you have done already) might just do the trick, no? Robin On Tue, Jul 14, 2020 at 14:58 -0700, Bob Murphy wrote: > > > On Jul 14, 2020, at 1:14 PM, Jon Siwek <jsi...@corelight.com> wrote: > > > > On Tue, Jul 14, 2020 at 11:56 AM Bob Murphy <bob.mur...@corelight.com> > > wrote: > > > >> The code you show should give correct ordering on when Foo() and Bar() > >> finish. > > > > Wondering what's meant by "correct ordering" here. Bar() can finish > > before Foo() and yet debug.log can report "I did Foo" before "I did > > Bar" for whatever thread-scheduling reasons happened to make that the > > case. Or Foo() and Bar() can execute together in complete concurrency > > and it's just the LockedDebugMsg() picking an arbitrary "winner". > > > > - Jon > > I see your point. > > For example: > a. Foo() in thread 1 finishes before Bar() in thread 2 finishes > b. The scheduler deactivates thread 1 for a while between the return from > Foo() and the execution of LockedDebugMsg("I did Foo.”) > c. Thread 2 proceeds from the return from Bar() without interruption > > Then debug.log would contain the message “I did Bar” before “I did Foo”. > > So the ordering in the log file really reflects how the kernel sees the > temporal order of mutex locking inside LockedDebugMsg. That’s an inexact > approximation of the temporal order of calls to LockedDebugMsg, and that’s an > even more inexact approximation of the temporal order of code executed before > LockedDebugMsg. > > For what I was doing, though, that proved to be good enough. :-) > > I’d be very interested in ideas about how to improve that, especially if > they’re simple. I can think of a way to improve it, but it would be > substantially more complicated than just a mutex. > > > > _______________________________________________ > Zeek-Dev mailing list > Zeek-Dev@zeek.org > http://mailman.icsi.berkeley.edu/mailman/listinfo/zeek-dev -- Robin Sommer * Corelight, Inc. * ro...@corelight.com * www.corelight.com _______________________________________________ Zeek-Dev mailing list Zeek-Dev@zeek.org http://mailman.icsi.berkeley.edu/mailman/listinfo/zeek-dev