[midPoint] Enviromental performance table in server task

Fri Feb 16 16:10:56 CET 2018

Hello Pavol,

I measured it again on one thread and results are similar:
*Task duration *(wall clock): 1365 seconds
*Provisioning operations* in total: 130 seconds
*Mappings* in total: 151 seconds
users:146
missing time total: 1084
missing time on one user: 7,47 seconds

I will try to do the trace log.

2018-02-16 15:20 GMT+01:00 Pavol Mederly <mederly at evolveum.com>:

>
>
>
> -------- Forwarded Message --------
> Subject: Re: [midPoint] Enviromental performance table in server task
> Date: Fri, 16 Feb 2018 15:03:43 +0100
> From: Pavol Mederly <mederly at evolveum.com> <mederly at evolveum.com>
> To: midpoint at lists.evolveum.com
>
> 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 developerevolveum.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 <+420%20774%20480%20101>
> e-mail: oskar.butovic at ami.cz
>
>
> AMI Praha a.s.
> Pláničkova 11
> 162 00 Praha 6
> tel.: [+420] 274 783 239 <+420%20274%20783%20239>
> web: www.ami.cz
>
>
> [image: AMI Praha a.s.]
>
> [image: 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 listmidPoint at lists.evolveum.comhttp://lists.evolveum.com/mailman/listinfo/midpoint
>
>
>

-- 

Oskar Butovič
solution architect

gsm: [+420] 774 480 101
e-mail: 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

[image: AMI Praha a.s.]

[image: 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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.evolveum.com/pipermail/midpoint/attachments/20180216/035b1549/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/035b1549/attachment.png>