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
>
