[midPoint] Enviromental performance table in server task
Pavol Mederly
mederly at evolveum.com
Fri Feb 16 15:03:43 CET 2018
Hello Oskar,
let us count:
*Task duration *(wall clock): 2:56.431 = 176,431 milliseconds
*Provisioning operations* in total: 191,274 milliseconds
*Mappings* in total: 135,583 milliseconds
Running in 8 threads, the task could spend 176,431 * 8 = 1,411,448
milliseconds.
In provisioning and mappings it spent 326,857 milliseconds.
So, what is "missing" are 1,084,591 millis.
But this is only a theory. During that "missing time", midPoint is doing
the following:
1. *Executing operations in repository.* This is not mentioned in the
Environmental Performance table, mainly because I haven't considered
repository to be "the environment" and so I have not implemented
measurement of those operations - although they could be viewed as
environmental in some situations, namely when DB guys are from
separate team and the database is performing badly :) Note that when
having 8 threads, there could be a strong contention during
repository access; so the times spent there could be significant.
2. *Internal midPoint logic.* Especially, operations executed in model
layer are not cheap, and they take their time.
3. *General overhead.* For example, individual threads have to be
started, synchronized, and so on. (I think this is not so much time,
though.)
... and maybe something more that I forget to mention.
However, it /is/ possible that some of the performance numbers are not
exact. I tried to implement them carefully, but there is a possibility
that some operations (maybe implemented after the performance measuring
framework was introduced) are executed without being accounted for. Or
maybe there's a stupid fault somewhere, like in aggregation of numbers
from all the threads. I remember I created a bug like that; but it's
fixed already. (To diagnose that you could, for example, run the task in
single thread, and see if the difference is still so large.)
I must admit that 1,084 seconds of missing time is 1,084/145 = about 7,5
seconds per object. This seems to be quite large amount. Maybe you could
really repeat the test in single-threaded environment and tell us the
numbers.
------------------------------------------------------------------------
Just for completeness: when diagnosing performance I sometimes employ
the following approach: I set the model logging to TRACE, sometimes also
provisioning to DEBUG or TRACE, and execute a single operation (e.g.
single import). Then I open the log in the log viewer and there I can
see the exact execution times for individual operations. Besides
learning about performance this view it is also very instructive,
because one can see details of midPoint processing; and generally we can
learn a lot from that.
However, using Environmental Performance tab is usually much simpler and
therefore more suitable.
Pavol Mederly
Software developer
evolveum.com
On 15.02.2018 14:40, Oskar Butovič - AMI Praha a.s. wrote:
> Hello everybody,
>
> I have noticed strange behavior during recent midPoint profiling.
>
> I am trying to profile and speed up reconciliation. It scales great
> with the number of CPUs. On the other hand, Environmental Performance
> tab in detail of the task shows clearly incomplete numbers. In the
> average sum of all total times gives only about 1/3 of total runtime
> of the task. Where is the midPoint other 2/3 of the time? How to find
> it out?
>
> For example reconciliation on 8 threads:
> Rekonciliace-YYYY
> Zpracování: 145 (ukončené)Poslední zpracovaný objekt: XXX
> 12.2.18 15:54:13 - 12.2.18 15:57:10 (00:02:56.431)
>
> *Informace o provisioningu*
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> *Připojená aplikace* *Třída objektu* *Získání OK* *Chyba* *Hledání
> OK* *Chyba* *Vytvořeno OK* *Chyba* *Aktualizace OK* *Chyba*
> *Smazání OK* *Chyba* *Synchronizace OK* *Chyba* *Skript OK*
> *Chyba* *Skript OK* *Chyba* *Všechny operace* *Prům. čas* *Min.*
> *Max.* *Celkový čas*
> AAA AccountObjectClass 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
> 0 1 46 0 3 46
> BBB Contact 142 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 142
> 55 30 853 7945
> CCC contact 120 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 120
> 132 15 13507 15950
> DDD inetOrgPerson 141 1 2 0 0 0 1 9 0 0 0 0 0 0 0 0
> 154 237 0 4500 36645
> EEE user 30 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 30 31 25
> 54 950
> EEE group 0 0 30 0 0 0 0 0 0 0 0 0 0 0 0 0 30 5 4
> 10 173
> FFF AccountObjectClass 31 0 0 0 0 0 0 0 0 0 0 0 0 0 0
> 0 31 7 6 13 246
> GGG ucet 3 0 0 0 0 0 3 0 0 0 0 0 0 0 0 0 6 1648
> 879 2601 9892
> HHH user 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 30 26
> 35 61
> III contact 65 0 0 0 0 0 2 0 0 0 0 0 0 0 0 0 67
> 1062 5 35850 71191
> JJJ user 34 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 34 1418
> 22 23909 48221
>
>
>
> *Informace o vyhodnocení mapování*
>
>
>
>
> *Obsahující objekt* *Počet zpracování* *Prům. čas* *Min.* *Max.*
> *Celkový čas*
> 1 427 0 0 1 71
> 2 5548 11 0 1027 65802
> 3 427 0 0 1 181
> 4 1708 23 0 255 39316
> 5 21777 0 0 155 4030
> 6 114 0 0 2 53
> 7 427 0 0 1 79
> 8 2816 0 0 161 772
> 9 2135 0 0 2 433
> 10 66 0 0 1 1
> 11 427 0 0 1 183
> 12 54 0 0 1 2
> 13 5246 0 0 37 2356
> 14 427 0 0 1 63
> 15 8340 0 0 163 1349
> 16 84 0 0 1 7
> 17 2950 6 0 177 18706
> 18 427 0 0 2 267
> 19 307 1 0 8 331
> 20 427 0 0 1 114
> 21 54 0 0 1 5
> 22 60 0 0 1 3
> 23 427 0 0 1 155
> 24 1147 0 0 19 993
> 25 9 0 0 1 1
> 26 96 0 0 1 17
> 27 66 0 0 1 12
> 28 24 0 0 1 7
> 29 16 0 0 1 3
> 30 27 0 0 1 4
> 31 573 0 0 1 106
> 32 148 1 0 139 161
> 33 9 0 0 0 0
> 34 3 0 0 0 0
> 35 3 0 0 0 0
>
>
>
>
> Thanks
> Best Regards
> OSkar Butovič
> --
>
> Oskar Butovič
> solution architect
>
> gsm: [+420] 774 480 101
> e-mail: oskar.butovic at ami.cz <mailto:oskar.butovic at ami.cz>
>
>
>
> AMI Praha a.s.
> Pláničkova 11
> 162 00 Praha 6
> tel.: [+420] 274 783 239
> web: www.ami.cz <http://www.ami.cz/>
>
>
>
> AMI Praha a.s.
>
>
> AMI Praha a.s.
> <http://www.ami.cz/reseni-a-sluzby/bezpecnost-dat/identity-management>
>
> Textem tohoto e-mailu podepisující neslibuje uzavřít ani neuzavírá za
> společnost AMI Praha a.s.
> jakoukoliv smlouvu. Každá smlouva, pokud bude uzavřena, musí mít
> výhradně písemnou formu.
>
>
>
> _______________________________________________
> midPoint mailing list
> midPoint at lists.evolveum.com
> http://lists.evolveum.com/mailman/listinfo/midpoint
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.evolveum.com/pipermail/midpoint/attachments/20180216/b89c9af3/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: mpaihocllklejmlm.png
Type: image/png
Size: 84717 bytes
Desc: not available
URL: <https://lists.evolveum.com/pipermail/midpoint/attachments/20180216/b89c9af3/attachment.png>
More information about the midPoint
mailing list