[
https://issues.apache.org/jira/browse/IGNITE-10493?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16724911#comment-16724911
]
Pavel Kovalenko commented on IGNITE-10493:
------------------------------------------
Timings in logs looks like this:
{noformat}
[2018-12-19 13:33:09,942][INFO
][sys-#322%database.IgniteDbMultiNodePutGetTest0%][GridDhtPartitionsExchangeFuture]
Exchange timings [startVer=AffinityTopologyVersion [topVer=3, minorTopVer=1],
resVer=AffinityTopologyVersion [topVer=3, minorTopVer=1], stage="Waiting in
exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms),
stage="Update caches registry" (144 ms), stage="Start caches" (56 ms),
stage="Affinity initialization on cache group start" (11 ms), stage="Exchange
type determination" (0 ms), stage="Preloading notification" (0 ms), stage="WAL
history reservation" (0 ms), stage="Wait partitions release" (0 ms),
stage="After states restored callback" (220 ms), stage="Waiting for all single
messages" (27 ms), stage="Affinity recalculation (crd)" (2 ms), stage="Collect
update counters and create affinity messages" (0 ms), stage="Validate
partitions states" (0 ms), stage="Assign partitions states" (1 ms),
stage="Ideal affinity diff calculation (enforced)" (6 ms), stage="Apply update
counters" (0 ms), stage="Full message preparing" (5 ms), stage="Full message
sending" (12 ms), stage="State finish message sending" (8 ms), stage="Exchange
done" (65 ms), stage="Total time" (557 ms), Discovery lag / Clocks discrepancy
= 13 ms.]
[2018-12-19 13:33:09,943][INFO
][sys-#322%database.IgniteDbMultiNodePutGetTest0%][GridDhtPartitionsExchangeFuture]
Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=3,
minorTopVer=1], resVer=AffinityTopologyVersion [topVer=3, minorTopVer=1],
stage="Affinity initialization on cache group start [grp=tiny]" (0 ms)
(parent=Affinity initialization on cache group start), stage="Affinity
initialization on cache group start [grp=non-primitive]" (0 ms)
(parent=Affinity initialization on cache group start), stage="Affinity
initialization on cache group start [grp=large]" (0 ms) (parent=Affinity
initialization on cache group start), stage="Affinity centralized
initialization (crd) [grp=tiny]" (0 ms) (parent=Exchange type determination),
stage="Affinity centralized initialization (crd) [grp=non-primitive]" (0 ms)
(parent=Exchange type determination), stage="Affinity centralized
initialization (crd) [grp=large]" (0 ms) (parent=Exchange type determination),
stage="Restore partition states" (0 ms) (parent=After states restored
callback), stage="Affinity recalculation (partitions availability) [grp=tiny]"
(0 ms) (parent=Ideal affinity diff calculation (enforced)), stage="Affinity
recalculation (partitions availability) [grp=non-primitive]" (0 ms)
(parent=Ideal affinity diff calculation (enforced)), stage="Affinity
recalculation (partitions availability) [grp=large]" (0 ms) (parent=Ideal
affinity diff calculation (enforced))]
{noformat}
> Refactor exchange stages time measurements
> ------------------------------------------
>
> Key: IGNITE-10493
> URL: https://issues.apache.org/jira/browse/IGNITE-10493
> Project: Ignite
> Issue Type: Improvement
> Components: cache
> Affects Versions: 2.7
> Reporter: Pavel Kovalenko
> Assignee: Pavel Kovalenko
> Priority: Major
> Fix For: 2.8
>
>
> At the current implementation, we don't cover and measure all possible code
> executions that influence on PME time. Instead of it we just measure the
> hottest separate parts with the following hardcoded pattern:
> {noformat}
> long time = currentTime();
> ... // some code block
> print ("Stage name performed in " + (currentTime() - time));
> {noformat}
> This approach can be improved. Instead of declaring time variable and print
> the message to log immediately we can introduce a utility class (TimesBag)
> that will hold all stages and their times. The content of TimesBag can be
> printed when the exchange future is done.
> As exchange is a linear process that executes init stage by exchange-worker
> and finish stage by one of the sys thread we can easily cover all exchange
> code base by time cutoffs.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
