Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
server-core
Code
Pull Requests
Issues
List
Boards
Iterations
Timesheets
Builds
Packages
Statistics
Child Projects
OneDev 10.9.4
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _server server-core Issues #1068
Improve LogFormat readability (and maybe performance) (#1068)
Closed
wojciech.kapcia@tigase.net opened 5 years ago

Attempt to improve formatter output
wojciech.kapcia@tigase.net commented 5 years ago

Before:

2019-08-28 19:44:56.891 [in_27-sess-man]   XMPPProcessor.canHandle()               FINEST:   XMPPProcessorIfc: MessageAmp (amp)
 Request: from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, conn: XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361], authorization: null
2019-08-28 19:44:56.891 [in_27-sess-man]   XMPPProcessor.canHandle()               FINEST:   XMPPProcessorIfc: PresenceSubscription (presence-subscription)
 Request: from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, conn: XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361], authorization: null
2019-08-28 19:44:56.891 [in_27-sess-man]   XMPPProcessor.canHandle()               FINEST:   XMPPProcessorIfc: ServiceDiscovery (disco)
 Request: from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, conn: XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361], authorization: AUTHORIZED
2019-08-28 19:44:56.891 [in_27-sess-man]   SessionManager.walk()                   FINEST:   XMPPProcessorIfc: ServiceDiscovery (disco)Request: from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, conn: XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361]
2019-08-28 19:44:56.891 [disco Queue Worker 0]  XMPPProcessorAbstract.process()    FINEST:   Calling method: processFromUserPacket, for packet=from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, for session=XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361]
2019-08-28 19:44:56.891 [disco Queue Worker 0]  XMPPProcessorAbstract.processFromUserPacket()  FINEST: Calling method: processFromUserToServerPacket, for packet=from=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get, for session=XMPPResourceConnection=[user_jid=alice@bee1.xmpp-test.biz/1935618115-tigase-1, packets=15, connectioId=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, domain=bee1.xmpp-test.biz, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1443037715, parentSession liveTime=1361]
2019-08-28 19:44:56.891 [disco Queue Worker 0]  ServiceDiscovery.processFromUserToServerPacket()  FINEST: forwarding packet to MRfrom=c2s@ip-10-0-47-247.us-west-2.compute.internal/10.0.47.247_5222_86.111.103.5_52494, to=sess-man@ip-10-0-47-247.us-west-2.compute.internal, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2019-08-28 19:44:56.891 [disco Queue Worker 0]  JabberIqPrivacy.filter()           FINEST:   Checking outbound packet: from=null, to=null, DATA=<iq to="alice@bee1.xmpp-test.biz/1935618115-tigase-1" from="alice@bee1.xmpp-test.biz/1935618115-tigase-1" xmlns="jabber:client" id="28DE08EC-E53D-4193-AC10-1F308AFFF348" type="get"><query xmlns="http://jabber.org/protocol/disco#info" node="http://tigase.org/TigaseSwiftX#GwOTmIbEUHs05F8gDVIVA+Z0DDw="/></iq>, SIZE=307, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2019-08-28 19:44:56.892 [disco Queue Worker 0]  JabberIqPrivacy.allowed()          FINEST:   Using privcy list: null

After:

[28-Aug-2019 21:08:40:103] [FINEST ] [       in_108-sess-man ] XMPPProcessor.canHandle()        : BlockingCommand (urn:xmpp:blocking), authorization/canHandle: null, Request: from=null, to=sess-man@atlantiscity.local, DATA=<message id="1" xmlns="jabber:client" to="admin@atlantiscity/Psi+/0" from="admin@atlantiscity"><event xmlns="http://jabber.org/protocol/pubsub#event"><items node="eu.siacs.conversations.axolotl.bundles:564699566"><item id="current"><bundle xmlns="eu.siacs.conversations.axolotl"><signedPreKeyPublic signedPreKeyId="1">CData size: 44</signedPreKeyPublic><signedPreKeySignature>CData size: 88</signedPreKeySignature><identityKey>CData size: 44</identityKey><prekeys><preKeyPublic preKeyId="1">CData size: 44</preKeyPublic><preKeyPublic preKeyId="2">CData size: 44</preKeyPublic><preKeyPublic preKeyId="3">CData size: 44</preKeyPublic><preKeyPublic preKeyId="4">CData size: 44</preKeyPublic><preKeyPublic preKeyId="5">CData size: 44</preKeyPublic><preKeyPublic preKeyId="6">CData size: 44</preKeyPublic><preKeyPublic preKeyId="7">CData size: 44</preKeyPublic><preKeyPublic preKeyId="8">CData size: 44</preKeyPublic><preKeyPublic preKeyId="9">CData size: 44</preKeyPublic><preKeyPublic preKeyId="10">CData size: 44</preKeyPublic ... , SIZE=9342, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=null, conn: XMPPResourceConnection=[user_jid=admin@atlantiscity/Psi+/0, packets=31, connectioId=c2s@atlantiscity.local/192.168.1.85_5222_192.168.1.85_51172, domain=atlantiscity, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=56794961, parentSession liveTime=570]
[28-Aug-2019 21:08:40:103] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Start element name: option
[28-Aug-2019 21:08:40:103] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Element attributes names: null
[28-Aug-2019 21:08:40:103] [FINEST ] [            amp-proc-0 ] XMPPSession.getResourceForResource(): Resource checking: Psi+/0, connectionID: XMPPResourceConnection=[user_jid=admin@atlantiscity/Psi+/0, packets=31, connectioId=c2s@atlantiscity.local/192.168.1.85_5222_192.168.1.85_51172, domain=atlantiscity, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=56794961, parentSession liveTime=570]
[28-Aug-2019 21:08:40:103] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Element attributes values: null
[28-Aug-2019 21:08:40:104] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Start element name: value
[28-Aug-2019 21:08:40:104] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Element attributes names: null
[28-Aug-2019 21:08:40:104] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.startElement() : Element attributes values: null
[28-Aug-2019 21:08:40:104] [FINEST ] [      pool-1-thread-11 ] DomBuilderHandler.elementCData() : Element CDATA: collection
[28-Aug-2019 21:08:40:103] [FINEST ] [       in_108-sess-man ] XMPPProcessor.canHandle()        : UrnXmppPing (urn:xmpp:ping), authorization/canHandle: null, Request: from=null, to=sess-man@atlantiscity.local, DATA=<message id="1" xmlns="jabber:client" to="admin@atlantiscity/Psi+/0" from="admin@atlantiscity"><event xmlns="http://jabber.org/protocol/pubsub#event"><items node="eu.siacs.conversations.axolotl.bundles:564699566"><item id="current"><bundle xmlns="eu.siacs.conversations.axolotl"><signedPreKeyPublic signedPreKeyId="1">CData size: 44</signedPreKeyPublic><signedPreKeySignature>CData size: 88</signedPreKeySignature><identityKey>CData size: 44</identityKey><prekeys><preKeyPublic preKeyId="1">CData size: 44</preKeyPublic><preKeyPublic preKeyId="2">CData size: 44</preKeyPublic><preKeyPublic preKeyId="3">CData size: 44</preKeyPublic><preKeyPublic preKeyId="4">CData size: 44</preKeyPublic><preKeyPublic preKeyId="5">CData size: 44</preKeyPublic><preKeyPublic preKeyId="6">CData size: 44</preKeyPublic><preKeyPublic preKeyId="7">CData size: 44</preKeyPublic><preKeyPublic preKeyId="8">CData size: 44</preKeyPublic><preKeyPublic preKeyId="9">CData size: 44</preKeyPublic><preKeyPublic preKeyId="10">CData size: 44</preKeyPublic ... , SIZE=9342, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=null, conn: XMPPResourceConnection=[user_jid=admin@atlantiscity/Psi+/0, packets=31, connectioId=c2s@atlantiscity.local/192.168.1.85_5222_192.168.1.85_51172, domain=atlantiscity, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=56794961, parentSession liveTime=571]
[28-Aug-2019 21:08:40:104] [FINEST ] [            amp-proc-0 ] Message.process()                : Delivering message, packet: from=null, to=sess-man@atlantiscity.local, DATA=<message id="1" xmlns="jabber:client" to="admin@atlantiscity/Psi+/0" from="admin@atlantiscity"><event xmlns="http://jabber.org/protocol/pubsub#event"><items node="eu.siacs.conversations.axolotl.bundles:564699566"><item id="current"><bundle xmlns="eu.siacs.conversations.axolotl"><signedPreKeyPublic signedPreKeyId="1">CData size: 44</signedPreKeyPublic><signedPreKeySignature>CData size: 88</signedPreKeySignature><identityKey>CData size: 44</identityKey><prekeys><preKeyPublic preKeyId="1">CData size: 44</preKeyPublic><preKeyPublic preKeyId="2">CData size: 44</preKeyPublic><preKeyPublic preKeyId="3">CData size: 44</preKeyPublic><preKeyPublic preKeyId="4">CData size: 44</preKeyPublic><preKeyPublic preKeyId="5">CData size: 44</preKeyPublic><preKeyPublic preKeyId="6">CData size: 44</preKeyPublic><preKeyPublic preKeyId="7">CData size: 44</preKeyPublic><preKeyPublic preKeyId="8">CData size: 44</preKeyPublic><preKeyPublic preKeyId="9">CData size: 44</preKeyPublic><preKeyPublic preKeyId="10">CData size: 44</preKeyPublic ... , SIZE=9342, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=null, to session: XMPPResourceConnection=[user_jid=admin@atlantiscity/Psi+/0, packets=31, connectioId=c2s@atlantiscity.local/192.168.1.85_5222_192.168.1.85_51172, domain=atlantiscity, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=56794961, parentSession liveTime=571]
[28-Aug-2019 21:08:40:104] [FINEST ] [            amp-proc-0 ] JabberIqPrivacy.filter()         : Checking outbound packet: from=sess-man@atlantiscity.local, to=c2s@atlantiscity.local/192.168.1.85_5222_192.168.1.85_51172, DATA=<message id="1" xmlns="jabber:client" to="admin@atlantiscity/Psi+/0" from="admin@atlantiscity"><event xmlns="http://jabber.org/protocol/pubsub#event"><items node="eu.siacs.conversations.axolotl.bundles:564699566"><item id="current"><bundle xmlns="eu.siacs.conversations.axolotl"><signedPreKeyPublic signedPreKeyId="1">CData size: 44</signedPreKeyPublic><signedPreKeySignature>CData size: 88</signedPreKeySignature><identityKey>CData size: 44</identityKey><prekeys><preKeyPublic preKeyId="1">CData size: 44</preKeyPublic><preKeyPublic preKeyId="2">CData size: 44</preKeyPublic><preKeyPublic preKeyId="3">CData size: 44</preKeyPublic><preKeyPublic preKeyId="4">CData size: 44</preKeyPublic><preKeyPublic preKeyId="5">CData size: 44</preKeyPublic><preKeyPublic preKeyId="6">CData size: 44</preKeyPublic><preKeyPublic preKeyId="7">CData size: 44</preKeyPublic><preKeyPublic preKeyId="8">CData size: 44</preKeyPublic><preKeyPublic preKeyId="9">CData size: 44</preKeyPublic><preKeyPublic preKeyId="10">CData size: 44</preKeyPublic ... , SIZE=9342, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=null

Changes are not that significant (move around level, wrap timestamp in square brackets, add a bit more of padding, but IMHO improves readability.

While working on it, it turned out that, considering tigase.util.log.LogFormatter as base, using String.format() would actually be roughly 30% slower, and a couple of tweaks would help improve it's performance roughly 50%

Benchmark                                    (formatterClass)   Mode  Cnt    Score    Error   Units
BenchmarkLogger.benchmark        tigase.util.log.LogFormatter  thrpt   15  115.071 ± 11.888  ops/ms
BenchmarkLogger.benchmark  tigase.util.log.LogFormatterSimple  thrpt   15   82.674 ±  5.046  ops/ms
BenchmarkLogger.benchmark    tigase.util.log.LogFormatterFast  thrpt   15  169.911 ± 12.269  ops/ms
BenchmarkLogger.benchmark        tigase.util.log.LogFormatter   avgt   15    0.193 ±  0.008   ms/op
BenchmarkLogger.benchmark  tigase.util.log.LogFormatterSimple   avgt   15    0.241 ±  0.025   ms/op
BenchmarkLogger.benchmark    tigase.util.log.LogFormatterFast   avgt   15    0.134 ±  0.004   ms/op

Results generated using JMH (Java Microbenchmark Harness) - this particular tests are stored in https://github.com/tigase/tigase-jmh-benchmarks/
issue 1 of 1
Type
Improvement
Priority
Normal
Assignee
wojciech.kapcia@tigase.net
Version
tigase-server-8.1.0
Spent time
12h
Related
  • tigase-private/systems-maintenance#73 You are not authorized to access this issue
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_server/server-core#1068
Please wait...
Page is in error, reload to recover