Hi there,
@Vladimir: thanks for your thoughts. Unfortunately I cannot get around the
issue by just tweaking the config. I tried all constellations fixing the
UserName/Properties etc. Looking at the code confirmes, that it just always
fetches the UserName from the System for each logging event, whether you use it
or not.
@Davyd: Thanks for the patch! I tried it out. It would sort out my issue.
Nevertheless, I think this patch would slightly break backwards compatibility.
The initial intention of the author of these lines:
// event properties
var eventProperties = new PropertiesDictionary();
eventProperties[UserNameProperty] = UserName;
eventProperties[IdentityProperty] = Identity;
compositeProperties.Add(eventProperties);
was, to make Username and Identity available in the Properties bag in order to
access them via the PropertyFilter. If you try to setup a PropertyFilter on a
RollingFileAppender for example and try to filter by UserName, it will no
longer work with the recent patch, because you haven’t explicitly fixed the
UserName and the PropertyFilter will fail looking up UserName. It’s just
impossible on a RollingFileAppender. You could argue, that the PropertyFilter
is not intended for filtering by UserName, but that’s what is possible now and
I think it is a reasonable feature.
I’m still of the opinion, that we shouldn’t add UserName and Identity to the
Properties bag. LoggingEvent.UserName is a regular property and caching/fixing
it is already implemented, so I don’t see why we should duplicate it in the
Properties collection. I think it should be the job of the
LookupProperty(string key) function to look for the correct property. I’ve
attached a patch to show what I mean.
Thanks and sorry for the bad responsivness
From: Davyd McColl <[email protected]>
Sent: Wednesday, February 23, 2022 7:51 AM
To: Vladimir Vedeneev <[email protected]>; [email protected]
Cc: Petker Denis 8BM3 <[email protected]>
Subject: *EXT* [Newsletter] Re: Re: [Newsletter] Re: log4net - performance hit
because UserName is fetched always
Hi Vladimir
(to clarify, from here on "fixed" refers to being unchanging, not reverted from
a broken state, and much of this message is for my own benefit as there are
still large portions of log4net that I'm not well-acquainted with)
I believe you're on the right track here - the added property information is
fixed alongside other properties like thread info, based on the flag
FixFlags.Properties. There's a bit of a mix of concerns, but basically:
- this only implicitly applies to appenders which derive from
BufferingAppenderSkeleton (eg AdoNetAppender, BufferingForwarding,
RemotingAppender, SmtpAppender, SmtpPickupDirAppender and any userland
derivative) or MemoryAppender - AppenderSkeleton derivatives (eg file
appenders) don't have such a flag and so can't pass it on to logging events.
- this can explicitly apply to logic where a consumer calls Logger.Log with an
instance of LoggingEvent they generated & where they set the Fix flag, but they
can also call the Log with a level, message and exception, and this will only
fix data where fixing is implicitly supported (see above)
- so if and when fixing occur is dependent on which appender is in use as well
as how the logger is invoked; ie YMMV
- implicit appenders set the Fix prop on the LoggingEvent based on
configuration (default for derivatives of BufferingAppenderSkeleton is _all_
data, including user/identity information!)
- this causes volatile data to be fixed
- what is fixed depends on the fixing flags for the LoggingEvent at hand
- if Properties are to be fixed, that fixes some thread information, including
UserName / Identity, even though there are specific flags for this
So my proposed change here is to observe the specific fixing flags for UserName
and Identity in CreateCompositeProperties (which is invoked whenever the Fix
flags are changed). See attached patch.
Thoughts?
-d
On 2022-02-22 20:37:58, Vladimir Vedeneev
<[email protected]<mailto:[email protected]>> wrote:
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
<[email protected]<mailto:[email protected]>> 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 <[email protected]<mailto:[email protected]>>
Sent: Tuesday, February 22, 2022 3:29 PM
To: [email protected]<mailto:[email protected]>
Cc: Petker Denis 8BM3
<[email protected]<mailto:[email protected]>>
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<http://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
<[email protected]<mailto:[email protected]><mailto:[email protected]<mailto:[email protected]>>>
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<http://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:
> > [email protected]<mailto:[email protected]><mailto:[email protected]<mailto:[email protected]>>;
> > Petker Denis 8BM3 <
> > [email protected]<mailto:[email protected]><mailto:[email protected]<mailto:[email protected]>>>
> > 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>
> > > (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
>
