Again not sure if this is applicable to your case, there are some discussions regarding UserName and performance in internet, like this one (with sql appender specifics) https://www.codewrecks.com/post/old/2015/03/bufferingappenderskeleton-performance-problem-in-log4net/
As a result they refer to Fix property https://logging.apache.org/log4net/release/sdk/html/T_log4net_Core_FixFlags.htm / FixFlags enum https://logging.apache.org/log4net/release/sdk/html/T_log4net_Core_FixFlags.htm which can be set to not fix UserName between thread (can you use that?) Again depends on appenders you use, but maybe helpful insight on "why" - as log4net needs to keep some properties based on current context, if logging event itself will be used in appenders later / in another thread etc when context is actually lost, and no way to restore those params, so they to be retrieved in advance Thanks, Vladimir On Tue, 22 Feb 2022 at 17:32, Denis Petker <denis.pet...@rohde-schwarz.com> wrote: > Hi Davyd, > > I’m not quite sure, whether I fully understood you. Our use-case is pretty > simple: we don’t use impersonating, we don’t log the username and we don’t > use the username for filtering log-events etc. So we are not interested in > username at all. Nevertheless, we are suffering from the slowness of > fetching the WindowsIdentity.GetCurrent().Name from the system. > The problem is that CreateCompositeProperties() unconditionally fetches > the username for each log-event and CreateCompositeProperties() is invoked > from various places. > E.g: we use a custom property registered in GlobalContext.Properties what > makes the LookupProperty(key) being invoked which in turn invokes > CreateCompositeProperties() for each log-event. > We also use the BufferingForwardingAppender and configure it with <fix > value="Partial"/>. That ends up calling > FixVolatileData->CacheProperties->CreateCompositeProperties for each > log-event as well. > > Although we are not using username, I don’t see a way to avoid fetching it > from the system using the latest version of log4net. > > If caching the username isn’t an option, my suggestion would be to get rid > of these lines from LoggingEvent.cs > // event properties > var eventProperties = new PropertiesDictionary(); > eventProperties[UserNameProperty] = UserName; > eventProperties[IdentityProperty] = Identity; > compositeProperties.Add(eventProperties); > > The reason for these lines was to make the username and identity available > in the LookupProperty function, so that a log-event filter (or whatever) > could make use of these. So from my perspective LookupProperty should be > responsible for fetching the username and identity when needed. Shall I > provide a patch to show what I mean? > > Btw: beginner question: how do I answer properly in order to append my > answer to the current thread in the mailing list, rather than creating a > new thread on each response? > > Thank you guys > Denis > > > From: Davyd McColl <dav...@gmail.com> > Sent: Tuesday, February 22, 2022 3:29 PM > To: dev@logging.apache.org > Cc: Petker Denis 8BM3 <denis.pet...@rohde-schwarz.com> > Subject: *EXT* Re: [Newsletter] Re: log4net - performance hit because > UserName is fetched always > > Hi Vladimir > > That's a very good point - the thread could be impersonating a user ( > https://docs.microsoft.com/en-us/dotnet/api/system.security.principal.windowsidentity.getcurrent > ), > and I could imagine this being the user for an asp.net request if it's > tied into windows identities. It is not the case for my work sites, where > `WindowsIdentity.GetCurrent()` > returns the "IIS AppPool" user (IIS APPPool\{pool name}) > > So it would seem that caching it isn't an option. It also looks like the > value is only calculated when read, so if it's not part of the logging > pattern, I don't see the problem? > Denis, can you elaborate on the use-case please? If your application never > impersonates, the value seems, to me, to have little value in logs, and if > it does impersonate, > then it should be updated. The edge case is multiple applications using > the same log4net configuration, without impersonation, where the user name > may change between > runs but not during the run of the process. Perhaps there should be two > properties: one cached and one not, bearing in mind that the original > behavior of the existing > UserName property (uncached) should probably be retained for the principle > of Least Surprise. > > -d > > On 2022-02-22 15:56:11, Vladimir Vedeneev <lanor...@gmail.com<mailto: > lanor...@gmail.com>> wrote: > Sorry if will be saying dumb things here, as I've seen that several years > ago and have no time to review that now; but maybe that'll ring the bell > for somebody > > I thought that UserName could be related to user name from principal (thus > basically anything set in code - and can be easily different for the same > thread in say asp.net environment), not the windows user name of the > process > > Thanks, > Vladimir > > On Tue, 22 Feb 2022 at 14:26, Dominik Psenner wrote: > > > I believe the caching has already been implemented but don't have any > > references to mention right now. > > > > On Tue, 22 Feb 2022 at 09:56, Denis Petker > > > > > wrote: > > > > > Hi Davyd > > > > > > Thanks for the quick response! Agreed, I also don't think, that the > > > username doesn't change for a process. > > > If we say, that the username isn't going to change for a process, I > think > > > there is no reason in printing the user name per log statement. > However, > > > the ticket LOG4NET-205 has been raised by someone, who obviously was > > > interested in filtering log events by username? > > > > > > So what you mean technically is to retrieve the username once at > startup > > > and cache for the remaining runtime? In order to be backward > compatible, > > we > > > then still need to maintain the UserName property in the LoggingEvent > > class > > > I guess. So the username would then be provided to LoggingEvent objects > > > from whatever is creating them? > > > > > > > > > -----Original Message----- > > > From: Davyd McColl > > > Sent: Monday, February 21, 2022 6:43 PM > > > To: dev@logging.apache.org<mailto:dev@logging.apache.org>; Petker > Denis 8BM3 < > > > denis.pet...@rohde-schwarz.com<mailto:denis.pet...@rohde-schwarz.com>> > > > Subject: *EXT* [Newsletter] Re: log4net - performance hit because > > UserName > > > is fetched always > > > > > > Hi Denis > > > > > > Thanks for the report (: > > > I'm happy to review contributions, though for this particular issue, it > > > seems like the resolution is to cache the resolved user name, rather > than > > > allowing specifying the name via config. The whole point of this > property > > > is to log the username under which the process is run (: The username > > for a > > > process isn't going to change (at least, I'm not aware of a process for > > > doing so), so it feels like the correct approach is simply to cache. > > Please > > > feel free to raise a PR at github. I recognise that I'm not the fastest > > > responder - there's just one of me and it seems like there's always > > > something vying for my attention - but I do try to respond to pull > > requests > > > as quickly as possible. > > > I have another fix in the works for xml layouts anyway, though I was > > > pursuing that with respect to another reported issue, but I could let > > that > > > issue go for now for a hastier release. > > > -d > > > On Feb 21 2022, at 7:22 pm, Denis Petker > > > > > > wrote: > > > > > > > > Hi all, > > > > > > > > we have upgraded the log4net version from 1.2.10 to the newest > version > > > 2.0.14 and are now facing performace issues. I already have done some > > > investigation looking at the log4net code. > > > > With the ticket LOG4NET-205 ( > > > https://issues.apache.org/jira/browse/LOG4NET-205) a change has been > > > introduced, which makes log4net not acceptable for us in terms of > > > performance. (Commit 5c023f6a22bfb93873a5ce0d6f5ac7e7275e2914) The > change > > > has been done in order to be able to use UserName and Identity in the > > > PropertyFilter. It adds 'internal' properties representing the UserName > > and > > > Identity to the m_compositeProperties so that they are now accessible > in > > > the PropertyFilter. That works as intended so far. See the attached > diff > > > illustrating the change. > > > > > > > > The problem is, that fetching the UserName from the system is pretty > > > expensive. With the change above UserName is fetched always, regardless > > of > > > whether we use UserName or not. I did some benchmarking and this change > > > slowed down logging by a factor of 60. I also don’t see any way to get > > > around this by changing the configuration. I believe this can only be > > fixed > > > by changing code. > > > > > > > > I would suggest, rather than adding 'internal' properties to > > > m_compositeProperties, we should make the function > > > LoggingEvent.LookupProperty to look after the native properties, when > > > corresponding keys are specified. E.g. when the key "UserName" is > > > specified, we could return the value of the property > > LoggingEvent.UserName > > > etc. > > > > > > > > In the meantime we want to use a changed version of log4net for our > > > purposes. I wonder, whether this change could be integrated into the > > > official version? I’ve never contributed to a public github project > > before, > > > so don’t know how to proceed really. > > > > > > > > Thanks, > > > > Denis > > > > > > > > > > > > This is the historic change causing the problem. > > > > > > > > > > > > -- > > > > Denis Petker > > > > Next Generation Solutions | 8BM3 > > > > > > > > > > > > > > > > Rohde & Schwarz GmbH & Co. KG > > > > Hanomaghof 1 | 30449 Hanover > > > > Phone: +49 511 678 07 146 | Fax: +49 511 678 07 200 > > > > Internet: www.rohde-schwarz.com<http://www.rohde-schwarz.com> ( > http://www.rohde-schwarz.com/) > > > > > > > > ------------------------------------------------------------ > > > > Geschäftsführung / Executive Board: Christian Leicher (Vorsitzender / > > > Chairman), Peter Riedel, Sitz der Gesellschaft / Company's Place of > > > Business: München, Registereintrag / Commercial Register No.: HRA 16 > 270, > > > Persönlich haftender Gesellschafter / Personally Liable Partner: RUSEG > > > Verwaltungs-GmbH, Sitz der Gesellschaft / Company's Place of Business: > > > München, Registereintrag / Commercial Register No.: HRB 7 534, > > > Umsatzsteuer-Identifikationsnummer (USt-IdNr.) / VAT Identification > No.: > > DE > > > 130 256 683, Elektro-Altgeräte Register (EAR) / WEEE Register No.: DE > 240 > > > 437 86 > > > > > > > > > > > > > > > > > -- > > Dominik Psenner > > >
