[ZBX-8542] A lot of semop and time functions while processing triggers Created: 2014 Jul 29  Updated: 2017 May 30  Resolved: 2014 Sep 26

Status: Closed
Project: ZABBIX BUGS AND ISSUES
Component/s: Server (S)
Affects Version/s: 2.2.5
Fix Version/s: 2.3.4, 2.5.0

Type: Incident report Priority: Trivial
Reporter: Alexey Pustovalov Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: performance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File strace.log    
Issue Links:
Duplicate

 Description   

Zabbix server uses a lot of slow time function (next snipped is strace output)

(time(NULL)                              = 1406628281)

while processing one iteration of history syncer (triggers evaluation).
Also Zabbix server tries to expand user macros in trigger expression by one. In this case Zabbix locks cache a lot of ones.

Please look log file to get more information.



 Comments   
Comment by Andris Zeila [ 2014 Aug 18 ]

(1) Create user macro cache that will be used to scan trigger expressions for user macros, resolve them with a single configuration cache lock and then use the resolved values in substitute_simple_macros() function.

RESOLVED in development branch svn://svn.zabbix.com/branches/dev/ZBX-8542

<dimir> CLOSED

Comment by Andris Zeila [ 2014 Aug 20 ]

(2) Create trigger macro cache that will be used for dependency checks and trigger value updates.

wiper RESOLVED

<dimir> was obsoleted, CLOSED

Comment by richlv [ 2014 Sep 01 ]

reopening, there's subissue 2

wiper forgot to change its status

Comment by dimir [ 2014 Sep 23 ]

(3) Trigger expressions processing became slower.

Some testing before and after these changes. Each host contains 10 items and 10 triggers. Every trigger expression contains all 10 items from the host. Every item contains user macro (from the host) as parameter (system.run[echo {$ZZZ<NUM>}).

Check out the time spent on evaluating 2000 triggers. It doubled at least after the changes.

Number of hosts 200
Number of items 2000
Number of triggers 2000
Required server performance, NVPS 200
Number of db syncers 8
Status time spent - seconds (tr - number of triggers processed, avg triggers per second)
Before changes 23557:20140923:185450.255 End of evaluate_expressions() time spent: 3.23 (2000 tr, 620.0 tr/s)
23557:20140923:185453.692 End of evaluate_expressions() time spent: 3.33 (2000 tr, 599.7 tr/s)
23557:20140923:185457.315 End of evaluate_expressions() time spent: 3.53 (2000 tr, 567.2 tr/s)
23557:20140923:185500.774 End of evaluate_expressions() time spent: 3.31 (2000 tr, 605.1 tr/s)
23557:20140923:185504.199 End of evaluate_expressions() time spent: 3.29 (2000 tr, 607.3 tr/s)
23557:20140923:185507.643 End of evaluate_expressions() time spent: 3.35 (2000 tr, 597.6 tr/s)
23557:20140923:185511.053 End of evaluate_expressions() time spent: 3.26 (2000 tr, 612.8 tr/s)
23557:20140923:185514.397 End of evaluate_expressions() time spent: 3.25 (2000 tr, 616.1 tr/s)
23557:20140923:185517.864 End of evaluate_expressions() time spent: 3.36 (2000 tr, 594.8 tr/s)
23557:20140923:185521.277 End of evaluate_expressions() time spent: 3.30 (2000 tr, 606.6 tr/s)
23557:20140923:185524.620 End of evaluate_expressions() time spent: 3.24 (2000 tr, 616.4 tr/s)
23557:20140923:185528.069 End of evaluate_expressions() time spent: 3.35 (2000 tr, 596.4 tr/s)
23557:20140923:185531.585 End of evaluate_expressions() time spent: 3.37 (2000 tr, 593.5 tr/s)
After changes 23502:20140923:182648.062 End of evaluate_expressions() time spent: 8.09 (2000 tr, 247.1 tr/s)
23502:20140923:182656.720 End of evaluate_expressions() time spent: 8.55 (2000 tr, 233.9 tr/s)
23498:20140923:182707.521 End of evaluate_expressions() time spent: 7.96 (2000 tr, 251.4 tr/s)
23498:20140923:182715.866 End of evaluate_expressions() time spent: 8.21 (2000 tr, 243.6 tr/s)
23498:20140923:182724.729 End of evaluate_expressions() time spent: 8.64 (2000 tr, 231.6 tr/s)
23498:20140923:182732.510 End of evaluate_expressions() time spent: 7.63 (2000 tr, 262.2 tr/s)
23498:20140923:182741.087 End of evaluate_expressions() time spent: 8.38 (2000 tr, 238.6 tr/s)
23498:20140923:182749.437 End of evaluate_expressions() time spent: 8.22 (2000 tr, 243.3 tr/s)
23498:20140923:182757.968 End of evaluate_expressions() time spent: 8.30 (2000 tr, 241.1 tr/s)
23498:20140923:182805.803 End of evaluate_expressions() time spent: 7.71 (2000 tr, 259.5 tr/s)
23498:20140923:182815.049 End of evaluate_expressions() time spent: 9.06 (2000 tr, 220.8 tr/s)
23498:20140923:182827.141 End of evaluate_expressions() time spent:11.80 (2000 tr, 169.4 tr/s)
23501:20140923:183159.336 End of evaluate_expressions() time spent:10.82 (2000 tr, 184.8 tr/s)

BTW, about 1000 items are queued for 10 seconds. Was tested on my workstation which has not much power and memory resources.

wiper On my system with loglevel set to 3 and 5000 hosts the macro cache had slight overhead (hard to evaluate, could be about 5%) during trigger expression processing, but the number of configration cache locks was greatly reduced.

Meanwhile I optimized the trigger expression function lookups, which gives nice performance improvement in this test scenario.
RESOLVED in r49348, r49406

<dimir> CLOSED

Comment by dimir [ 2014 Nov 04 ]

(4) [D] More like a suggestion. Would be great if you could describe in the code using block-scheme or something the way trigger expressions are now evaluated. How macro cache and other helper data structures are generated and used.

wiper RESOLVED in r50496

<dimir> Looks great! CLOSED

Comment by dimir [ 2014 Nov 04 ]

Great performance improvement on substitute_functions()! Now trigger evaluation time dropped dramatically (I used DebugLevel=3 here):

Status time spent - seconds (tr - number of triggers processed, avg triggers per second)
Before changes 17619:20141104:174031.121 End of evaluate_expressions() time spent: 2.64 (2000 tr, 756.5 tr/s)
17619:20141104:174033.504 End of evaluate_expressions() time spent: 2.37 (2000 tr, 842.6 tr/s)
17619:20141104:174036.104 End of evaluate_expressions() time spent: 2.57 (2000 tr, 778.5 tr/s)
17619:20141104:174038.755 End of evaluate_expressions() time spent: 2.64 (2000 tr, 757.0 tr/s)
17619:20141104:174041.468 End of evaluate_expressions() time spent: 2.70 (2000 tr, 739.7 tr/s)
17619:20141104:174043.826 End of evaluate_expressions() time spent: 2.35 (2000 tr, 851.8 tr/s)
17619:20141104:174046.280 End of evaluate_expressions() time spent: 2.44 (2000 tr, 818.0 tr/s)
17619:20141104:174048.869 End of evaluate_expressions() time spent: 2.58 (2000 tr, 775.6 tr/s)
17619:20141104:174051.630 End of evaluate_expressions() time spent: 2.75 (2000 tr, 728.3 tr/s)
17619:20141104:174054.003 End of evaluate_expressions() time spent: 2.36 (2000 tr, 846.4 tr/s)
After changes 8535:20141104:190114.399 End of evaluate_expressions() time spent: 0.16 (2000 tr, 12740.4 tr/s)
8531:20141104:190115.328 End of evaluate_expressions() time spent: 0.18 (2000 tr, 11427.0 tr/s)
8534:20141104:190118.710 End of evaluate_expressions() time spent: 0.18 (2000 tr, 10904.2 tr/s)
8536:20141104:190118.994 End of evaluate_expressions() time spent: 0.15 (2000 tr, 13236.3 tr/s)
8539:20141104:190119.508 End of evaluate_expressions() time spent: 0.15 (2000 tr, 13220.1 tr/s)
8537:20141104:190120.426 End of evaluate_expressions() time spent: 0.14 (2000 tr, 14704.8 tr/s)
8530:20141104:190123.736 End of evaluate_expressions() time spent: 0.18 (2000 tr, 11106.0 tr/s)
8532:20141104:190124.018 End of evaluate_expressions() time spent: 0.16 (2000 tr, 12502.3 tr/s)
8535:20141104:190124.563 End of evaluate_expressions() time spent: 0.15 (2000 tr, 13446.7 tr/s)
8531:20141104:190125.490 End of evaluate_expressions() time spent: 0.15 (2000 tr, 13608.1 tr/s)
Comment by dimir [ 2014 Nov 06 ]

Successfully tested.

Comment by Andris Zeila [ 2014 Nov 07 ]

Released in:

  • pre-2.5.0 r50498
Comment by Andris Zeila [ 2014 Nov 07 ]

(5) Documented at https://www.zabbix.com/documentation/3.0/manual/introduction/whatsnew300?&#daemon_improvements

<dimir> Added bit more details, please check.

wiper Thanks, CLOSED

Comment by Andris Zeila [ 2014 Nov 11 ]

(6) Whitespace should not be removed during expression evaluations. See the patch:

Index: src/libs/zbxserver/expression.c
===================================================================
--- src/libs/zbxserver/expression.c	(revision 50540)
+++ src/libs/zbxserver/expression.c	(working copy)
@@ -3865,7 +3865,6 @@
 		tr = (DC_TRIGGER *)triggers->values[i];
 
 		tr->expression = zbx_strdup(NULL, tr->expression_orig);
-		zbx_remove_whitespace(tr->expression);
 
 		/* add trigger macros to user macro cache */
 		zbx_umc_add_expression(&macro_cache, tr->triggerid, tr->expression);

The whitespace removal apparently slipped from 2.2 branch, which was the branch the development was based on initially.

<dimir> Right, CLOSED

Comment by Andris Zeila [ 2014 Nov 11 ]

Fixed in development branch svn://svn.zabbix.com/branches/dev/ZBX-8542

Comment by Andris Zeila [ 2014 Nov 11 ]

Released in:

  • pre-2.5.0 r50545
Generated at Fri Apr 19 03:08:51 EEST 2024 using Jira 9.12.4#9120004-sha1:625303b708afdb767e17cb2838290c41888e9ff0.