Machida in examples/python/celsius-kafka is idle at 100% cpu time

[slfritchie]

I'm looking at the release branch at commit de92121, both with & without resilience enabled(*) on OS X. When I see run machida process as described by the examples/python/celsius-kafka/README.md example while idle (both the test-in and test-out topics are empty), the machida process consumes an entire CPU core. Other examples in that directory & at that commit don't have the same behavior, though I've only checked the word count example at the same commit.

git checkout de9212133cc0936dc9045f3d2aa365d2e070154f
( cd machida ; make clean ; make )
echo 'Take manual steps to stop Kafka, remove test-* topic log data, start Kafka'
rm -v /tmp/*initial*
cd examples/python/celsius-kafka
env PYTHONPATH=".:../../../machida" ../../../machida/build/machida --application-module celsius --kafka_source_topic test-in --kafka_source_brokers 127.0.0.1:9092 --kafka_sink_topic test-out --kafka_sink_brokers 127.0.0.1:9092 --kafka_sink_max_message_size 100000 --kafka_sink_max_produce_buffer_ms 10 --metrics 127.0.0.1:5001 --control 127.0.0.1:12500 --data 127.0.0.1:12501 --external 127.0.0.1:5050 --cluster-initializer --ponythreads=1

(*) I once thought that resilience=on vs. off made a difference. It does not, AFAICT.

[SeanTAllen]

I believe that would be because the other examples are tcp which is push vs kafka which is a pull mechanism. I don't think this is a machida issue, I believe we need a new tag for kafka and that machida isn't really involved in this. The same issue would I suspect impact any other API.

@dipinhora thoughts?

[dipinhora]

The cpu usage is definitely because of the KafkaSink and KafkaSource combined with --ponythreads=1. Both sink and source have an underlying KafkaClient and each KafkaClient has an underlying connection to every Kafka Broker. Each connection to a Kafka Broker, has to poll to check for new messages (once every 0.1 second by default). Additionally, there is also a periodic metadata refresh that happens automagically (once every 300 seconds by default). For KafkaSink that polling should be disabled because we never registered any topics to consume from.

There is likely room for improvement on the KafkaClient side of things to make polling more efficient and to also tweak the defaults to use less cpu at the expense of how quickly messages are consumed from Kafka. However, the bigger limitation for us will be our forced use of --ponythreads=1 when using machida. Especially when connecting to Kafka Clusters with multiple brokers (since this would result in multiple tcp connections behind the scenes and prior experience with pony market spread performance testing has indicated that each tcp connection effectively needs it's own dedicated cpu core for optimal performance). This same issue would impact any machida applications under load even when they're not using Kafka.

[SeanTAllen]

@dipinhora can you open any relevant issues on the kafka-client and here, create any labels to track as needed, add to projects as needed and then we can close this issue out in favor of the newly created issues?

[dipinhora]

@SeanTAllen WallarooLabs/pony-kafka/issues/41 created for the idle polling optimization on the pony-kafka side of things.

I still feel there's the additional angle of the --ponythreads=1 limit for machida that needs to be addressed.

[SeanTAllen]

What angle is that @dipinhora? I'm not sure what having 1 thread has to do with it. Other than all polling will stay on a single cpu. And what there would be to address with that.

[dipinhora]

@SeanTAllen It seems I wasn't clear. The 100% cpu issue in this ticket has nothing to do with --ponythreads=1 except that it consolidates load that would otherwise be spread across multiple cores as you mentioned.

The place where --ponythreads=1 becomes an issue is with performance scaling under load (not when idle as this ticket is about) and that is the angle I was referring to (and tried to explain in the second paragraph of #1584 (comment)). I feel this needs to be addressed in some form (maybe it already has been addressed with a decision to always limit to 1 core intentionally, even if embedded python doesn't require it, and I'm missing the context?).

[SeanTAllen]

@dipinhora i'm not sure what the correct way to interpret that is. I think there is a lot of context and assumptions you are making that I'm not sure of so any answer I give might lead you astray.

Are you saying we should be locking and unlocking the GIL so that none python code in machida can run at the same time as the python interpreter?

[dipinhora]

@SeanTAllen I'm not familiar enough with Python internals, nor the vagaries of embedded python to make any meaningful statements regarding what should or shouldn't happen with the GIL in machida as related to the embedded python interpreter.

I'm ignoring the python related implications in the following statement:

--ponythreads=1 is a performance issue for machida when scaling under load

The above statement is based on the following logic/context:

• Based on prior experience with load testing of pony market spread we know that under load every TCPSource/TCPSink actor in pony effectively ends up needing a full core (or else performance suffers)
• pony-kafka uses a TCP actor under the scenes that is very similar to TCPSource and TCPSink
• pony-kafka creates multiple TCP connections (one to each kafka broker in a cluster) when it is used by either KafkaSource or KafkaSink
• Machida allows for the use of KafkaSource or KafkaSink
• Python celsius-kafka uses machida and it's support for KafkaSource and KafkaSink but the instructions specifically indicate that need for --ponythreads=1
• Using --ponythreads=1 for python celsius-kafka prevents the multiple TCP connection actors create by the KafkaClient from having dedicated cores.
• Therefore, when python celsius-kafka is run under load, we are almost guaranteed to have a performance bottleneck caused by the use of --ponythreads=1
• Additionally same issue would impact any machida applications under load even when they're not using Kafka (for example any application that uses multiple TCPSources/TCPSinks).

Hopefully the above helps clarify my thought process and any context that I may have previously left out in regards to my statement that "--ponythreads=1" is a performance issue for machida when scaling under load.

[dipinhora]

@slfritchie I just ran celsuis-kafka idle on linux (ubuntu in a vm) and the cpu usage was only about 11%.

Can you confirm which OS you encountered the 100% cpu usage on?

[slfritchie]

@dipinhora OS X Sierra (10.12.6) plus XCode 9.0.

[dipinhora]

Thanks. I'll try and reproduce on my older version of OS X.

[SeanTAllen]

@dipinhora the OSX idling issue was at least partially address a couple months back on mainline pony.

[SeanTAllen]

@dipinhora re: more than 1 thread. we can do some work with that but in the end python is basically single threaded. we can only ever execute one thread of python code at a time. it will be inherently slower because of that given that we will need to distribute work to other processes. Anyway, that is off topic for this issue.

[dipinhora]

@SeanTAllen Re: the OSX idling issue, if you're referring to ponylang/ponyc#1787, I don't believe it's been resolved in mainline pony.

[dipinhora]

@SeanTAllen Re: more than 1 thread, I'll open a separate issue because it seems we're currently limiting all of machida to a single thread because of our use of python even though the core of wallaroo that machida relies on is mostly pony actors which can run concurrently (see the Kafka broker connections scenario described earlier as one example of such a scenario). Yes, it will inherently be slower than pony versions of the same program but right now it is slower than it needs to be due to the single threaded execution of everything when only the python bits need to be single threaded. This is not to say it would be easy or possible to run machida with multiple threads while the embedded python is limited to being single threaded.

[SeanTAllen]

@dipinhora re: threads, @aturley and i have had several conversations on that.

[slfritchie]

FWIW, the pure pony version uses 2 CPU cores at idle.

PID    COMMAND          %CPU TIME     #TH   #WQ #PORTS MEM    PURG   CMPRS  PGRP  PPID  STATE    BOOSTS       %CPU_ME %CPU_OTHRS UID FAULTS    COW     MSGSENT    MSGRECV    SYSBSD     SYSMACH    CSW        PAGEINS IDLEW    POWER USER            #MREGS RPRVT VPRVT VSIZE KPRVT KSHRD
64589  celsius-kafka    180.8 06:10.42 6/2   0   23     2384K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1439+     83      50+        15         696983386+ 79         152494+    5       0        180.8 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    199.9 06:12.49 6/2   0   23     2388K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1440+     83      50         15         701080933+ 79         152703+    5       0        199.9 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    199.9 06:14.55 6/2   0   23     2392K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1441+     83      50         15         705100941+ 79         152898+    5       0        199.9 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    200.0 06:16.61 6/2   0   23     2392K  0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1441      83      50         15         709091388+ 79         153085+    5       0        200.0 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    199.5 06:18.68 6/2   0   23     2396K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1442+     83      50         15         713018826+ 79         154090+    5       0        199.5 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    199.3 06:20.74 6/2   0   23     2400K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1443+     83      50         15         717010086+ 79         155502+    5       0        199.3 scott           N/A    N/A   N/A   N/A   N/A   N/A  
64589  celsius-kafka    200.0 06:22.81 6/2   0   23     2404K+ 0B     0B     64589 781   running  *0[1]        0.00000 0.00000    502 1444+     83      50         15         720984022+ 79         155749+    5       0        200.0 scott           N/A    N/A   N/A   N/A   N/A   N/A  

[SeanTAllen]

I believe that is an OSX only issue that was partially addressed (but not fully) in mainline Ponyc.

[dipinhora]

@slfritchie Did @SeanTAllen's ponyc fix for OSX busy polling (ponylang/ponyc#2254) resolve this for you?

[slfritchie]

Yes. Well, mostly. The idle time of machida_resilience plus celsius_kafka has dropped from 100% down to about 13-15%. Given that the Kafka client is polling every 100msec, and that Pony's work stealing is still busy-waiting for short periods of time, the 13-15% is expected. It would be nice if it were yet much lower, but #41 can probably help substantially.