Compact logging mode incorrectly groups log messages

[hannobraun]

Hi there,
this is a screenshot of log output from my application:

As you can see, the various Starting.../Finished. messages have different values for the middleware key.

Here's the same output in compact mode:

Suddenly all the messages are grouped under the first middleware.

I've reviewed the slog/slog-term code to figure out how this can be and found this function that looks dubious to me:

slog/src/lib.rs

Line 659 in 26d13bf

pub fn id(&self) -> usize {

The function returns the id for an OwnedKeyValueList, using the address of self as the id. Although I haven't confirmed it, I believe this is the source of my problem. Even if not, I believe it to be wrong anyway. The function ignores the fact that an OwnedKeyValueList could be dropped, and a new created in its place.

I believe this is what's happening in my case. I'm creating a new Logger with some additional data, use it to log some messages, then it falls off the stack and I create the next one. Since nothing really happens between the dropping of a Logger and the creation of the next one, it makes sense that they would all end up with the same address on the stack, causing all the OwnedKeyValueLists to have the same id.

[dpc]

Thanks for the report. I think you're right on your diagnosis. The way you use logger (from your description) makes it so that different logger can get the same address.

We'll figure out something. Right now I'm guessing that actually comparing the number of addresses and where there point to could be as fast, and eliminate problems like that.

[hannobraun]

Why not do away with the notion of an id, and make formatting decisions based on the data itself? Performance reasons?

[dpc]

Performance, yes.

I've pushed a branch with fix based on atomic counter.

The cost:

cargo benchcmp old new --regressions
 name                                         old ns/iter  new ns/iter  diff ns/iter  diff % 
 log_stream_async_empty_json_blackbox_log_10  143          149                     6   4.20% 
 log_stream_async_json_blackbox_10            475          504                    29   6.11% 
 log_stream_async_json_blackbox_log_10        136          142                     6   4.41% 
 log_stream_json_blackbox_10                  1,378        1,379                   1   0.07% 
 log_stream_json_blackbox_i32closure          925          938                    13   1.41% 
 log_stream_json_blackbox_i32pushclosure      920          930                    10   1.09% 
 log_stream_json_blackbox_i32val              921          923                     2   0.22% 
 log_stream_json_blackbox_strpushclosure      958          964                     6   0.63% 
 logger_new_empty                             21           25                      4  19.05% 
 logger_new_nonempty                          52           57                      5   9.62% 
 logger_new_nonempty_10                       60           66                      6  10.00% 
 tmp_file_write_1kib                          362          369                     7   1.93% 

[hannobraun]

I can confirm that this fixes my problem. Thanks!

[dpc]

Thanks. So the question now is, is the price worth it (+5ns when creating every Logger instance).

I'm thinking what other approaches could be used to keep the compacting functionality.

[hannobraun]

I don't think I can really help you with that decision. It would definitely be worth the cost to me, but my use case is not that performance-sensitive. I'd imagine there are use cases that are a lot more demanding, and I can't really speak for those.

[dpc]

I'm still thinking about it. The performance is once thing, the other one is the counter itself, that would only be 32-bit on 32-bit architectures. (and potentially smaller CPUs).

I wish the was a better way.

[dpc]

OK. So it seems to me the current method is a premature and just wrong optimization (as @hannobraun noted). The code is trying to be smart about not serializing unnecessary things for performance reason, but it does not work in this case, and it also incorrectly skips data in case of eg. closures that might change their values. It's better to take the small performance hit in case of using compact formatting then add needless counters affecting all users.

Instead of ids, everything should be serialized at all times, and results (serialized data) compared. Only then can results be trusted.

The id notion will be deprecated, and slog-term fixed not to use it.

[dpc]

Main fix pushed in slog-rs/term@85d3cf0 and commits around it.

[dpc]

Closing. Feel free to reopen.

[hannobraun]

Your fix doesn't work, unfortunately. The problem, as I originally described it, persists. I'm looking into it now to figure out what the cause is.

Unfortunately I can't seem to reopen the issue, for some reason.

[hannobraun]

Please ignore my last comment. While I was in fact testing with the latest master branch of slog (and had verified that fact multiple times before posting here), I was still using the latest release of slog-term, which of course didn't contain the fixes.

Sorry for the mistake, and thanks a lot for the fix!

[dpc]

👍 Thanks for confirming it.