January 26, 2012

Figuring out where the server spends time

The UnboundID products offer unique observability features to help understand how deployments behave and where to improve.
One of them is the sup-operation timer, a facility allowing to peek into processing times for operations of interest.
First, we need to enable it:
$ dsconfig set-global-configuration-prop --set enable-sub-operation-timer:true
$ dsconfig create-log-publisher --publisher-name "Operation Timing Access Log" --type operation-timing-access --set enabled:true --set log-file:logs/operation-timing --set "rotation-policy:24 Hours Time Limit Rotation Policy" --set "retention-policy:File Count Retention Policy"


Then we'll search the database so we have something to look at

# bin/ldapsearch -b o=demo "(uid=user.0)"
/usr/bin/tput: unknown terminal "xterm-256color"
/usr/bin/tput: unknown terminal "xterm-256color"


Arguments from tool properties file:  --hostname localhost --port 9389
--bindDN o=i --bindPasswordFile config/i.pwd


dn: uid=user.0,ou=People,o=demo
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetOrgPerson
postalAddress: Aaren Atp$01251 Chestnut Street$Panama City, DE  50369
postalCode: 50369
description: This is the description for Aaren Atp.
uid: user.0
userPassword: {SSHA}Xbl7h2+tKwok2OQ2CsPcI1QmWpdZfyHkvGp+Ng==
employeeNumber: 0
initials: ASA
givenName: Aaren
pager: +1 779 041 6341
mobile: +1 010 154 3228
cn: Aaren Atp
sn: Atp
telephoneNumber: +1 685 622 6202
street: 01251 Chestnut Street
homePhone: +1 225 216 5900
l: Panama City
mail: user.0@maildomain.net
st: DE


Finally, we can look at how this operation was processed and where the server spent the time. It is important to note that the times here are in microseconds except for "etime" (in milliseconds), the decimals would therefore be nanoseconds, providing the most fine-grained information on processing time we can to help you figure out where you will get the most bang for the buck trying to optimize your service. Let's have a look:


# vi logs/operation-timing 

[21/Jan/2012:14:56:17 -0600] SEARCH RESULT conn=7 op=111665 msgID=111666 base="o=demo" scope=2 filter="(uid=user.1)" attrs="ALL" resultCode=0 etime=0.038 entriesReturned=1 mostExpensivePhase="SENDING_RESULT" mostExpensivePhaseTimeMicros=19.030 mostExpensiveAggregatePhase="SENDING_RESULT" mostExpensiveAggregatePhaseTimeMicros=19.030 phaseTimesMicros="CREATING_OPERATION=1.434 ENQUEUEING=2.815 RUNNING=0.452 INVOKING_PRE_PARSE_PLUGINS=0.069 PARSING_OPERATION_WIDE_REQUEST_CONTROLS=0.242 LOGGING_REQUEST=0.259 WAITING_ON_THREAD=2.297 CHECKING_CLIENT_CONNECTION_POLICY=0.289 SELECTING_SUBTREE_VIEW=1.800 CREATING_WRAPPED_OPERATION=0.092 ATTACHING_BACKEND_OPERATION=0.380 BEGINNING_PROCESS_OPERATION=0.090 HANDLING_TRANSACTION_CONTROL=1.225 HANDLING_REQUEST_CONTROLS=0.050 CHECKING_ACL_OPERATION_ALLOWED=0.266 INVOKING_PRE_OPERATION_PLUGINS=0.084 INVOKING_BACKEND_PROCESSING=0.285 JE_BACKEND_ENTRY_CONTAINER_SEARCH=0.617 JE_BACKEND_ATTRIBUTE_INDEX_EVALUATE_EQUALITY_FILTER=0.422 JE_BACKEND_INDEX_READ_KEY=0.113 JE_BACKEND_DB_READ=5.109 JE_BACKEND_ENTRY_CONTAINER_SEARCH_INDEXED=0.322 JE_BACKEND_ID2ENTRY_GET=0.102 JE_BACKEND_DB_READ=2.549 JE_BACKEND_ID2ENTRY_DECODE=13.422 BEGINNING_RETURN_ENTRY=0.202 CHECKING_ACL_ENTRY_ALLOWED=0.707 PREPARING_ENTRY_FOR_RETURN=4.006 CHECKING_ACL_FILTER_ATTRIBUTES=0.361 INVOKING_SEARCH_ENTRY_PLUGINS=0.083 SENDING_SEARCH_ENTRY=2.014 LOGGING_SEARCH_ENTRY=0.358 INVOKING_POST_OPERATION_PLUGINS=0.228 SETTING_PROCESSING_STOP_TIME=0.098 SENDING_RESULT=19.030"


Some subtitles may help, so let's look at a few things:
etime -highlighted in blue- stands for elapsed time. It totals at 38 microseconds here.
That is the total time between the server being handed the tcp packet(s) by the operating system, processing the request and returning a response. So it is the server-side perception of the elapsed time.


 As you can see, the most time consuming phase in the processing of this operation was actually putting the result back on the wire to get the result back to the client. It may seem like a small number but if you put that in perspective, since the entire processing time was 38 microseconds, spending 19 to send the result to the client means we are effectively spending 50% of the time waiting for I/O, which is indeed quite enormous.


So that is all, just one more thing to help get to the bottom  of performance optimizations...

No comments:

Post a Comment