ZABBIX upgrade to v4, some pure load test

As a final part of work i want to upgrade all to v4 line to be able to support the changes as long as possible with minimum efforts. (And to work as early adopter and bug fixer for Zabbix)

I have also decided to do some pure untouched virgin Zabbix load tests.

I took clean v4.0.0 alpha 9, applied clickhouse changes.

By the way i saw some minor elastics changes, but what is more important - they seem to be implemented file offloading of events, history, trends, perhaps something else.

That is valuable. Perhaps if found this before, the clickhouse offloading would be implemented outside if the main server process as a file parser. On the other hand, current implementation is in process, efficient and also frontend-compatible.

The reason to do load test is a to find that maybe Zabbix will be able to do out of the box what we want it to do.

This time i've tried to fetch as much SNMP traffic as possible:

pic: (1) system is 44% loaded, but (2) collecting only 21-22k new values per 5 seconds, so it's 5-6k NVPS. It's spends 10-12 seconds (4) in waiting for configuration locks, under normal conditions poller processes spends 4-5 seconds per each 50-60 values. Totaly, there are 3500(!) (4) poller threads running. And they also exhausted most of the memory.

I couldn't make it run more then 4k threads out of the box, but assuming linear CPU growth it will be able to grow to 8k after some sysctl fixes and gather 12k NVPS in the best case.

Then i've decided to test again pure accessibility check speed. As i mentioned before, i could acheive 28k NVPS on the same machine of pure accesibily 1-packet check on fixed icmp module which utilizes nmap instead of fping.

Ok, pure fping. System is quite loaded. Load average is 466 :), no idle time, 10-11kNVPS performance.

So, Zabbix cannot do alone out of the box what we need and there is a reason to apply fping and snmp patches, since they really make it possible to collect 15 times more data on the same hardware.

Wow, Thats Funny! 100k NVPS exceeded!

Subject is inspired by on of the most popular TED YouTube videos.


I was recently doing load testing of the new code altogether and found a funny thing:

After certain point lowering delay for items leads to dramatic degradation of preprocessor manager.


I've  added statistics logging to worker threads and found out that they are free most of the time, so this time it looks like it's the preprocessor manager problems.

After reducing items delay to something less then 30 seconds i saw that preprocessor managers drop their processing speeds from around 80 000 items to 500-800 items per 5 seconds.

 

pic: semop 4 shown, but real problem is the semop 1

Perhaps, it's still locking. There aren't that many semop operations, according to strace, but visually it's the operation where the process freezes most. I couldn't find a simple way to calculate wait time via strace or something similar, so have to rely on my eyes. (update: RTFM, -w  -c options combined  produces strace statistics based on real time)

First i've found prerproc_sync_configuration was guilty, but this was wrong path.

After an hour of research i've found another bottleneck. And this one is also global architectural - it the history cache locks.

Situation is almost the same as it was with configuration lock. There is a globally locked access to history storage which leads to "single CPU problem"

Having LOTS of results coming from pollers, threads become limited by a single core speed to put data to the cache and to read it from.

Solution? Well, it nothing new - lets split it to 4 independent caches which is locked separately and access each one by it's sets of threads.

Most of dbcache.c has to be fixed as it's not only the cache that has to be split into 4 parts, but there are lot's of static vars declared.

Not sure if this is something needed for production but a might be a good prototyping experiment.

It is also a question hanging - why performance raises when i split preprocessing manager to 4 workers on Xeon5645 CPUs? (upd: perhaps the answer is that preprocessor manager has lots of other processing work to do which being split by differnt CPUs give some combined profit)

Whatever.

Just to make sure the job of maximizing NVPS is completed,  i fixed dbcache.c and HistoryCache locking to support 4 hsitory caches to see if this is _the last_ bottleneck.

I did what i assume safe locking - rare and non critical operations are still lock the entire cache operations, but most critical ones - only locks it's part of the cache.

Data flush from preprocessor manager to cache, where speed is mostly needed, are done by locking one of four sub caches, and such an additions can go in parallel. Then i also had to fix lots of static vars in dbcache.c as they seem to be used in parralel.

But i have to admit i've failed on this experiment. Spent 3 day's free time, but still was getting very unreliable daemon which keep crashing after 1-2 minutes.

So at the moment i am giving up on this, perhaps later i may revert to this.

pic: four preprocessor managers, doing 118k NVPS combined (note - idle time calculated wrong)



And there is one more reason.

I returned to test machine with E3-1280. And wow!, Zabbix could poll, process and save 118kNVPS (pic) with fixed queueing and 4 preprocessor managers. I would say its 105-110k stable while still having 18-20%idle. And It's kind a lot. My initial goal was to reach 50k. Considering we need 10k on one instance and 2k on the other it's enough capacity to grow for a while.

ZABBIX: multiple preprocessing managers

I decided to do that due to one thread of Xeon5645 couldn't handle all the preprocessing job, and also this might be required for faster CPU's but for higher loads.

First, some thoughts i had ahead:

• 1.there might be a problem if two dependent items go to different managers so they will be waiting one another (deadlock)
• 2. It must be some kind of workers distribution.

My first idea was to split requests and responses to threads, but then i decided it will be much easier to solve 1 and 2.

Since there was already host-to-queue persistence in queuing version, so i did thread-to-preprocmanager persistence the same way (procnum%4). So all items from each host will get to the same preprocessing manager.

Workers are split by preprocessing managers in the same way, by hashing thair procnum.


So, after fixing the worker log handling problem, preprocessors could handle much more requests.I saw stable value around 110k per 5 seconds per each manager, giving altogether 88k NVPS. I thought of making a 100k, but decided not to waste time on this old hardware, but test something more up to date later.

By the way, measuring prprocessor manager statistics is the way how i prefer to measure NVPS. I assume server collects a bit more from the network. It does requests to inaccessible hosts, which return no data and don't appear at preprocessing manager.

So thats it. Splitting preproc manager is essential if there is a need to achieve more then 50k NVPS stable on modern CPU's. This is what actually was limiting the test server with Xeon E3-1280.

ZABBIX: the second server

Tried to launch ZABBIX with all the fixes on the role of servers monitoring, started to segv.This was a bug in error logging.

There is another (big?)
problem there:

 

It looks like poller needs to be further altered to support asynchronous checks for agents.Or there some kind of locking occurs.

Strange thing that simple checks are slow too. Or might be global thing like DNS or something

This installation is rather small: 

And the server is sure enough idle 97%.

upd: nothing interesting, new server was not permitted by ip filters to access hosts via SNMP, and for agents there was also no permittion to it to request data. 

ZABBIX: what does a cat when it have a free time?

subj. ZABBIX does something quite opposite.

I had successfully changed the code to have as many preprocessor managers as i want.

But whatever i did, stuck at 60k nvps.
My initial thought was it's preprocessor manager slows things down. So i've rewrite it to have 4 managers.

But then i saw that running 4 managers spreads CPU load between them, but gives no NVPS increase.

Whatever i thought, i couldn't find a reason to such a behavior. But today it struck me - it's worker threads and workers are waiting for them.

So, i straced worker thread.

.. semop....
Ok, is it GLOBAL config LOCK again?

NO, it's mutex 0, the mutex dedicated for logs.
But i don't see anything from workers in logs and it is loglevel is 3.

And guess what?
Let me show you the main loop of worker code:

 

I commented it out. It does log rotation. With locking. Inside loop which runs possibly in 100 threads and which task is to process an item as fast as possible.

So all the worker threads was keep trying to put LOG lock and to rotate the log file if it's bigger then config values. I guess it's a developers mistake. 

So, without log handling workers could do a bit faster and server achieved approximately 85-90kNVPS, while having only 25% idle. 

So, perhaps, that's the limit for double  E5645 system with 12 physical cores (and total 24 cores if we count hyper threaded ones).

During all this tests i've also found preprocessor manager priority flaw - it was more likely that it will gather queues before the buffer is full. And when the buffer is full it would be working OK, but it would be slowing down pollers.

Now it's just fine. Queue is close to zero. Each one of managers writing about 110k items each 5 seconds. So totally it is 110k*4threads/5seconds=88kNVPS.

ZABBIX: crashtesting, records #2

....failed very fast, on lots of process the system starts to swap

fixed the buffer, the system does fine with 20 snmp threads with, about 25knvps

have significant queuening with 43k required nvps, try to make 30 threads


didn't help, changed delay from 90 to 120, zabbix somehow stopped to work normallu, restarted.

doesn't work either, reduced numbre of pollers to 20
queueing, 33nvps.....
raised pollers back to 40....

OK, 30NVPS ONLY SNMP - NO PROBLEM
changed back delay to snmp to 90s.... lets look
it still queueng but just above 10sec, at planned load of 43knvps

reduced delay of snmp to 100 sec,pinger still off, let' see
ok, the system is stable to complete zero queues at 33kNVPS of clean SNMP load.

Now, let's test the FPING 100 threads:
the old version could handle the load without big broblems with up to 1sec (1sec had quieuieng in the first column)

NMAP: 100 threads works worse then FPING
high system load,  32% idle

Reduced NMAP threads to 20:
It does just like 100 threads FPING but system idle is 62%

Reduced NMAP threads to 10: it's worse, 20 seems more optimal, it's 82% idle

Now try fping in 20 threads:

The normal SNMP is:
0:00.26 /usr/local/sbin/zabbix_server: poller #1 [got 249 values in 5.005509 sec, getting values]                                
 7942 zabbix    20   0 13,670g 271628 213924 S   0,3  1,7   0:00.26 /usr/local/sbin/zabbix_server: poller #4 [got 175 values in 4.851671 sec, getting values]                                
 7943 zabbix    20   0 13,670g 265808 208076 S   0,3  1,6   0:00.25 /usr/local/sbin/zabbix_server: poller #5 [got 142 values in 4.914348 sec, getting values]                                
 7946 zabbix    20   0 13,670g 268228 210508 S   0,3  1,6   0:00.25 /usr/local/sbin/zabbix_server: poller #8 [got 175 values in 5.141629 sec, getting values]                                
 7947 zabbix    20   0 13,670g 274664 216944 S   0,3  1,7   0:00.26 /usr/local/sbin/zabbix_server: poller #9 [got 158 values in 5.044240 sec, getting values]                                
 7949 zabbix    20   0 13,670g 264984 207320 S   0,3  1,6   0:00.24 /usr/local/sbin/zabbix_server: poller #11 [got 184 values in 5.038127 sec, getting values]                               
 7951 zabbix    20   0 13,670g 273344 215680 S   0,3  1,7   0:00.27 /usr/local/sbin/zabbix_server: poller #13 [got 138 values in 4.924217 sec, getting values]                               
 7953 zabbix    20   0 13,670g 287580 229860 S   0,3  1,8   0:00.27 /usr/local/sbin/zabbix_server: poller #15 [got 172 values in 5.133177 sec, getting values]                               
 7955 zabbix    20   0 13,670g 258828 201032 S   0,3  1,6   0:00.24 /usr/local/sbin/zabbix_server: poller #17 [got 142 values in 4.982964 sec, getting values]            

140-150 per thred per 5 seconds
tried to make 300 threads



fping synthetic results:
 fixed fping
real    0m42,646s
user    0m0,236s
sys    0m0,336s


total CPU usage: 0,572s

fping normal

real    1m33,304s
user    0m0,104s
sys    0m0,276s
total CPU usage: 0,380s

nmap
real    0m3,252s
user    0m0,220s
sys    0m0,076s
total CPU usage: 0,296s

ZABBIX: crashing, getting syssegvs and so on -dairy records

And still i see the server is failing (segv sometimes).
It's not nearly as stable as the production one but tipycally these problems are quite easy to catch

The problem now is that server restart is taking more and more time (about 2-3 minutes)



The preprocess manager problem



The questions:

"something impossible happen logs"

why snmp is slow to be enabled? - figure why unreachible threads are waiting for nothing



huge load after some time!!!! net_snmp_close()???

in the night had huge number of must use snmp_select_socket2 (or so messages) - seems that under certain conditions i leave opened SNMP sessions.
Too many sessions cause high load and what seems to be select() call is not working, so essentially  all the gathering process breaks
TO DO: add some profiling, look where i may leave sessions unlclosed, consider removing (select) code and replacing by stupid simple wait call.


morning: huge snmp queue, seems that threads work normaly, i haven't found any abnormalies, just 10 them is not enought. (actually, they work much longer then at start, their run time raized from 6-9 seconds to 14-25, but that might be due high system load)

Raised snmp pollers number to 25, starting at 08:08
8 58 flight normal queue 0

seems something strange has happen at 11 24-11 34, apparently serever has crashed at that time, there is a long queue in SNMP in the browser left
11 41 started again ... actually the server is alive, but is't swapping and there are 16M records in the queue of the preprocess manager.

Myabe that's just too much hosts???
Maybe that's too big load from fpings
Now i disabled about 20k hosts, reduced number of threads to 20 for both pingrer and poller, restarted  the server, let's see what's happen


Having only half of the load (and also number of DB Syncers increased to 40) system is seems to be doing fine for at least 1 hour for now. And this is the time when i finaly see some SNMP data gathered in the graphs.

I will look at it for another 2 hours then will start gradually adding new devices.
UPD so far evth is fine, no queueing, system 90% idle


Another problem to consider - devices marked non - snmp acessible stay too long in such a state and i've never saw any processing done by unreachible pollers.
I exect i've broken some fetching logic in DC functions and that makes it such a long to mark devices as SNMP accessible again


So my theory is: 1.  I haven't enought data syncer processes enabled before so they where constantly busy in filling the value cache (ClickHouse not really fast for single host queries). Acutally i would suggested to fill the cache on the start by some bulky way - this would mean one query with millions of data. Unfortunately, i am not sure if this is what really zabbix and it's triggers need.


 The biggest thing that bothering me right now is occasional preprocessing manager queueng. I am almost sure that the queuing depends on two factors: system load and number of working threads (actually it might be one of them, and this two factors are closely linked). There one big optimization that could be done on the SNMP poller - is to enable bulk queriing, this will save some ticks of CPU and network PPS, might be easier for network devices, but it will not faster things really as anyway each SNMP thread will be waiting for inacessible devices timouts which more longer than making 100 queries to accessible device, and they happen in parralel in the asyncronious model.

Another big change and improvement that might be made is switching from fping to nmap for hosts checking. Question one - is how valuable the packet loss rates for understanding device reachibility. I have a thought that it might be more valuable to make 10 pings each 3 seconds then make them all at once each 30 seconds. In such a way of checking the packet loss rate will be done in a trigger by calculating average on base of last 5-10 checks. To speed up reaction of a device has become non accessible, last 2-3 checks must be considered.


ok, morning, 3 17. I see that the installation has crashed in preprocessing manager caught syssegv.

All pingers has been off (i've set up StartPingers=0)

I really believe that it's preprocessing manager that has to be blamed, in particular,  queueing of items. So, i'd like to fixid to one of the following
- find an answer - why is queuing happening at all???
- do not allow queueng
- after certain amount of queueing throttle the processes to wait till preprocessing manager be free (if it's load problem, which seems not)

I have nice thing - i know that running zabbix in debug mode almost immediately causes the queueuing. So i need to trace down all the decision process to understand, why the hell does it queues the messages


I see that most of it's time it's spend processing IPC requests of type 2 (probably, that the result of the poller's work). added extra flush and history flush logging to see if it's happening at all. On the next step will add _flush call result