Logging optimization.2 14 #944
Conversation
|
Hi @vancem, I'm your friendly neighborhood .NET Foundation Pull Request Bot (You can call me DNFBOT). Thanks for your contribution! The agreement was validated by .NET Foundation and real humans are currently evaluating your PR. TTYL, DNFBOT; |
| @@ -18,7 +18,11 @@ internal static class HostingLoggerExtensions | |||
|
|
|||
| public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext) | |||
| { | |||
| return logger.BeginScope(new HostingLogScope(httpContext)); | |||
| // to avoid allocation, return a null scope if the logger is not on at least to some degree. | |||
| if (logger.IsEnabled(LogLevel.Critical)) | |||
There was a problem hiding this comment.
Test better before the RequestScope call to in CreateContext?
|
The reasoning from before was that scopes are global. You might have logging on for just MVC and not include hosting, but now you have none of the request scope info. That's my recollection of why we didn't do this before. I don't recall anything being broken.... |
|
Right. That's broken 😄 |
|
Right, it's an observable behavior change, not just a perf optimization. |
|
I think it is perfectly reasonable to make Scopes follow the same rules as events (that is they can be filtered) There are several reasons for this but the most obvious is simply the pay for play aspect. If logging is off, then it should be off, and having scopes be 'always on' even when they serve NO purpose is pretty questionable design (keep in mind this overhead will be repeated for anything that might want to have a scope) But even without the pay-for-play aspect, it seems very reasonable that you want control over scopes in the same way you want control over filtering of events. If we had a security system, and it had a scope, but I did not care to monitor that aspect of the system, I should not have the overhead of tracking security scopes. Thus it seems perfectly reasonable to require that scopes should honor the filtering criteria. Since scopes are so useful, you probably want them on if you are logging most everything else (thus tie it to error or critical is reasonable), but there is room for debate there (since frankly turning on scopes is relatively expensive you could argue they should only be turned on for warnings or even info). Note that this model is not so bad. It does require that anyone who want 'HTTP' scopes needs to turn on the HTTP ILogger to at least that level. I think that is very reasonable, and I really don't see the problem (it makes intuitive sense that I would not see HTTP scoping information unless I asked for it in some way. I understand it is an observable change. However but I would argue that that does not rule out the change. At worst it makes logging less informative, but it is also something that can be 'fixed' by users by updating a config file, which makes it far less impactful. The issue here is are we really serious about making our logging system pay for play (close to no overhead when it is off). If so, we should fix our public contract to make that so sooner rather than later. Off really needs to mean off... |
|
Yeah to be honest I don't know how bad it is to have scopes be unavailable in this case. I don't recall the exact circumstances when it is problematic. Having said that, I believe that perf w/ logging enabled is far more important in the real world compared to perf w/o logging, because we expect all real apps to have logging enabled. I get it that we want certain benchmarks to be fast, but we also have to be careful about optimizing scenarios that aren't reflective of the real world. For example, consider a hypothetical case where we have So, while I agree that off really needs to mean off, I'm not sure I'm on the same page as to whether logging has to actually have an "off" switch. (As opposed to what it has right now, which is apparently more of a "don't be so loud" switch.) |
|
I'd feel more comfortable if the logger factory had an |
|
They are slightly different things; switching off security is testing a broken system; switching off logging isn't. It certainly makes it a less helpful system, but its not broken.
Don't see a conflict; you'd want the The performance without logging is important as the benchmark comparisons being made are to frameworks without logging enabled; and paradoxically, increasing the performance without logging, will increase the number of apps that will be made where the performance with logging is important. On the other hand logging is often it is a bottleneck; due to a very parallel system often being placed on top of a very serial logging framework with global locks. So the system may scale up, but the logging doesn't. Maybe want to benchmark at various levels of bells and whistles switched on? e.g. logging, etw, activity tracing, app insights, etc and determine where improvements need to be made... |
Now I'm just being a troll, but security isn't a must when you're working in a closed system that by design accepts only trusted inputs. Imagine some closed system that uses the loopback adapter for all communications and doesn't allow remote connections. But back to non-troll-land... I think this:
Is perhaps more fitting here. I've thought about it some more, and I think that my earlier comment was true but I wasn't sure why at the time:
I think that what logging has right now really is a "don't be so loud" switch and perhaps the So, the question to everyone is: Should logging have a total and explicit Off switch? |
|
Coming back to this. @Eilon made the comment that the 'logging off' case is not the 'important' case because we expect the 'real world' to have logging on. My counter point however, is they WILL want this instrumentation to be light weight. In particular they are VERY likely to use SAMPLING. Thus either particular nodes, or particular times the logging system will be OFF (thus it will only be on 10% or even 1% of the time). This seems VERY real world to me, especially at scale. Now I can't do sampling if the logging system can't be turned off (it places a real lower bound on the overhead on the system). Thus it really is very important that the system can be turned off and when it is off it is as cheap as possible. Having Scopes be unconditionally on is simply problematic. It is also important because frankly we have multiple logging systems, and so any particular logging system (e.g. ILogger), may not be used (I may be only using DiagnosticSource). Under those conditions why should I have to pay for ILogger overhead that I am not using at all. So to answer @Eilon question, Yes, logging should have a total off switch, because that is the switch that I will use to make sampling work. I also think that we don't have to invent anything new. We just need to make Scopes follow the same filtering criteria as any other pieces of data in the data pipeline (I only get them if I asked for them). This is very reasonable After thinking about it I think I would turn Scopes on only at the Warning level (the code right now turns them on for Critical). I could live with just about anything however, because the difference is only about what happens at Error and Critical and I don't really have good experience in what people actually find important (are the scopes critical in understanding Errors? If not scopes don't need to be on for Errors). |
|
Let's just make a breaking change to the logging interface then. We can add an IsEnabled to the logger factory. That will remove the ambiguity so we can just call that to know if anybody is listening then turn off scopes if that's the case. |
|
How does InEnabled() differ from IsEnabled(Critical) ? It feels like a another level below Critical but why is that useful? Presumably the idea of IsEnabled() is that you would use it to filter logging of Scopes. But I would argue that Scope are probably too verbose for Critical (when you say you only want critical messages, you presumably did so because you wanted the overhead to be as low as possible). Thus I would only make Scopes log for 'Critical' verbosity if they were necessary to interpret critical messages. My point, however is that like event, some scopes are 'super important' (because are valuable for interpreting data in 'super important' critical events, and other scopes are not as important because they only are only valuable in interpreting more verbose logging messages. Thus you probably want verbosity on Scopes (just like ALL OTHER LOGGING). You can have a default (e.g. Warning or Error, I suggest Warning), and call it a day. For what it is worth. In the end my main thing is that I want off to mean off, but as a more minor point, treating scopes like any other kind of logging (thus respects verbosity), seems very reasonable way of doing it. |
Why is that? Why would I want my scoping information removed because I wanted to see only critical logs within that scope? The 2 things seem completely unrelated.
The problem is we don't know that they aren't critical. |
I am arguing that scoping information is just information. And as you point out the logging system really can't judge how important that information is without being told. Thus I am arguing that when you do a BeginScope() you should tell the logging system how important THAT PARTICULAR Scope is. If it is important to decode critical events, then it should be Critical. If it is only important for Informational events, then it can be informational. If you want to be 'safe' you can of course make all BeginScope 'Critical' (which means they are on if the logger is on at all), which is what I did in this PR, but of course you now sacrifice brevity (now to get even the least verbose messages from the logger, you must have the overhead of any scopes). Maybe that is the right choice and maybe it is not. My main point is that the producer of Ilogger messages is in a better position to make that call than ILogger itself. If everyone decides that there scopes are Critical, great. I just don't want ILogger to force that choice. For what it is worth. |
|
But Also if there are no listeners it returns a non allocating NullScope |
|
@benaadams it'll be on unless it's off 😄 . @vancem we'll merge this. Even though it's not perfect, breaking the logging API has other downsides for little benefit at this point (and even then it won't be perfect). |
In my TechEmpower benchmark I noticed we were allocating a HostingLogScope on every request. This is completely unnecessary. Fix it so that we only allocate this scope when logging is actually on.