Aerospike server got very high CPU usage when using with the php-client

We have an issue while using php client. In our situation, we have 5 aerospike servers ( version 3.5.15) and 10 php servers. On each php server, we have 500~1000 php-fpm processes.

After deployed on php server with php-client, the aerospike servers got very high CPU usages (1200% above on 24 cores machine), even there is only few active write request.

we have enabled the persistent connection flag on the php client. It seems the client connections from php to server is very high (over 700 on each server). However, most of the connections are not in heavy load. I think the aerospike server should handle idle connections efficiently.

And with the perf top -p $AS_PID I can see the 10%~15% percent is used by the get_random_replica function. I saw this function is removed since 3.6.0, but I am not sure is this the whole truth that cause the high CPU usages.

Is there any reason to cause so high CPU usage and how to fix this?
Thanks.

Hi @Vincent_Lee. I started answering this issue on a different discussion post:

Should we continue there?

Maybe we should continue here. I think the server can be optimized to handle large idle connections.

We are currently trying to do more test with aerospike.shm.use = 1 enabled and we currently set the max_requests=50000.

We will see if any improvement.

We have done the stress test. With the aerospike.shm.use = 1 enabled, only a little improved.

The test is running with 300+ php-fpm processes on single machine.

When the server client connections showed over 700, the CPU usage is reaching 1000%+ on 24 cores machine. And I tried the server version 3.6.4 has the same issue.

Again, understand that it only trims 1 connection thread per-process when you use shared-memory cluster tending. The issue is still that you have 2*N connections per-process where N is the number of nodes in the Aerospike cluster. Multiply that by 300-700 and you get the idea.

Drop the number of concurrent FPM processes, keep the max_requests at a high number, and see what impact that has.

Reduce the fpm processes is not possible currently. Maybe we need do some proxy connections between the php and server. Also I think maybe it is possible for the aerospike server to handle large idle connections more efficiently.

Wait, you can’t configure your own PHP server? The Aerospike server already handles a very large number of concurrent connections. Your problem is on the PHP app nodes, not the Aerospike server nodes. It’s the amount of CPU being used by way too many concurrent FPM processes, each of them holding an Aerospike client under the covers.

In an environment like Java and C# all the operations happen from a single, high-performance Aerospike client. Since PHP is set up to run as shared-nothing, those processes cannot share a client, and must all hold their own.

Therefore, you need to reduce the number of concurrent FPM processes, increase the number of requests each of those make. Less overhead spent on initializing the process, and less clients on a single node. It’s not that complicated to test.

Anyway, at some point you can show your FPM config, and your Aerospike client (ini) config.

No, The high cpu usage is on the aerospike server, not on the php server. config as below:

pm.max_children = 2000 
pm.max_requests = 5000

aerospike.shm.use = true
aerospike.shm.max_nodes = 32
aerospike.shm.max_namespaces = 32
aerospike.shm.takeover_threshold_sec = 30
aerospike.use_batch_direct = 1

running state:

We currently can not reduce fpm processes because currently we need it to do more other work.

Understand that having hundreds to thousands of clients on a machine with 24 is going to be problematic. The Aerospike client is a heavy client - it keeps track of the state of the cluster, it connects to each of the nodes directly, at least two connections per-node. It’s all in the manual, but I can point out the links if you can’t find it.

What is your server like? What hardware is it on, what does the configuration file look like?

Have you checked the logs for errors? Take a look at ‘not enough file descriptor errors’ in Troubleshooting, and information about the proto-fd-max config setting.

There is no error logs on the aerospike server and the proto-fd-max = 15000.

Each server has 24 CPU cores (Intel(R) Xeon(R) CPU E5-2630 v2 @ 2.60GHz) with 64GB memory.

The log on the server should be, by default, in /var/log/aerospike.log. Check there.

You have a one node cluster, or how many nodes are in this Aerospike cluster?

I know the log location and I have reviewed the content and no error log, just info log.

In test environment, we have 3 nodes in the cluster.

I turned on the debug log on the demarshal, and seeing lots of Sending Info request via fast path. . Maybe the php client can reduce the info request frequency when idle?

I think the reason is the info_thread, after I changed the info-threads to low and the cpu usage can be reduced.

I turned on the microbenchmarks log, and see most is info requests, part of logs as below:

Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads (6000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000005996) (01: 0000000004)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_cleanup (2000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000002000)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_net (2000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000002000)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_net (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_storage_read (500 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000000500)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_storage_open (500 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000000500)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_tree (2000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000002000)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_internal (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_internal (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_start (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_start (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_q_process (2000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000002000)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_q_process (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: q_wait (2000 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000002000)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: demarshal_hist (62828 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000062828)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: wt_master_wait_prole (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_prole (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_resolve (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_resolve (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: reads_resolve_wait (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: writes_resolve_wait (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: error (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: batch_index_reads (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: batch_q_process (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: info_tr_q_process (60828 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000060828)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: info_q_wait (60828 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::154)  (00: 0000049021) (01: 0000002537) (02: 0000003486) (03: 0000004845)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::154)  (04: 0000000645) (05: 0000000194) (06: 0000000085) (07: 0000000015)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: info_post_lock (60826 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::154)  (00: 0000030925) (02: 0000003206) (03: 0000025100) (04: 0000001595)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: info_fulfill (60827 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::163)  (00: 0000060827)
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: write_storage_close (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: write_sindex (0 total) msec
Nov 25 2015 03:03:49 GMT: INFO (info): (hist.c::137) histogram dump: prole_fabric_send (0 total) msec

Hope these details can give any help to do more improvement for the future.

Please try the new client release 3.4.6 and read the Configuration in a Web Server Context section of the overview.

Thank you for your work. It works better with shm enabled with new client.