Is it me, or the GIL?

Speaker 1 [00:03]

Hi, I would like to start with a very short question. So, who is aware of the Python Global Interpreter Log? Okay, who likes the Python Global Interpreter Log? Okay, who had problems with the Python Interpreter Log? Okay, we will see. Maybe we can fix some of the problems. But first of all, I would like to give you some bit of background, what I'm actually doing. I'm actually a software engineer, but I don't know why I'm always doing quality assurance all the day. Basically, I'm doing quality assurance inside of a team of SAP for SAP HANA, which is a big in-memory database for enterprise products and so on. HANA itself is not written in Python, but all the tests are written in Python. All the test infrastructure is written in Python. That also means that we run a huge test infrastructure to do quality assurance. is one of our main pillars for quality assurance. And we are testing around 800 commits every single day. And therefore, we run a slight small infrastructure of 1,600 machines with a lot of memory. In-memory database lives in memory. We need a lot of memory. So we have, at the moment, around 610 terabyte of memory, but that changes over time, all the time. And, yeah, I'm actually a software engineer. So, what I do is develop software, develop services, develop tools for this infrastructure. And as I have written Python, I'm now here to talk a bit about that. And regarding the problem, my problem with the GARN, I would like to show you how we actually run tests and how we distribute tests across our servers. Therefore, we actually have a dedicated framework, a dedicated task distribution framework, which is built on top of Apache Mesos. And Apache Mesos is something like Kubernetes. It's a bit older than Kubernetes. Therefore, it's not so cool than Kubernetes and so on. Nevertheless, at the end, Apache Mesos receives various kinds of resource offers from our various data centers, cloud providers, and so on. Methods will send over these resource offers to our task scheduler. Our task scheduler is responsible to take tasks from our test scheduling and then schedule certain tasks, certain tests on the available resources. And the task scheduler itself is a big application. It's integrated with various other services, also known persistency and so on. But the good thing is the task scheduler is written in Python. Therefore, everything is solved, basically. Until we actually had a small problem, which is a luxury problem, because we added more and more machines in our data centers. And at some point, we basically had scalability issues. So our task scheduler received so many incoming messages with so many available resources and status updates and so on, that it was actually not fast enough anymore to schedule new tasks on top of the available resources, which is a bit of a problem if you cannot really utilize all your available resources. And one theory that we now had is, okay, we have to take a deeper look into the task scheduler. We need to optimize that. And to understand how the task scheduler internally works, I have a small semantic overview of that. We have a lot of threads. So it's written in Python. We have a lot of threads. It should be okay because, I mean, we have a lot of I.O. traffic and I.O. work. So we are doing, for example, in various threads, I.O. requests to databases, to other services, and so on. they will release the gill, everything is fine, so it will scale well. That was the assumption. But it didn't work out so well, and we have now to analyze the problem. The good news is, we actually have also an observability stack which should support us in analyzing that. So the first thing that we did is actually taking a look on, okay, what is our author handling thread doing? So, that's the thread who receives all the incoming offers of resources and tries to schedule work on that offers. This is a semantic overview of the thread, how the thread goes over various offers. And there are some quite interesting spots which look a bit suspicious. And I would like to go through them. So the first thing is there are operations which should run in the same time, but there are different run times of the same operation, which is a bit strange, especially there's a huge variance of the runtime. The second thing is with our distributed tracing approach, we could also see how long CERN operations take in the upstream or downstream service. So in this particular example, the task scheduler is doing a request to another service. Within the task scheduler, it looks like the request takes around 200 milliseconds, but the other service is actually reporting, I processed the request in 30 milliseconds. This looks also a bit strange. And the third thing is that there are certain gaps between operations which should actually not occur. You can see on the prepareTask operation, it runs in 545 milliseconds, and it should only contain two API calls, but there are certain gaps in between, which is a bit strange. the assumption was now and because i mean we are talking about threats and people would like to get rid of threats and so on okay it must be something with the girl there are threats they they're releasing the girl and then they have a hard time actually to reacquire the global interpreter log and therefore we have now a performance problem but the nice thing is actually we can easily mitigate the GIL contention. There are various ways to mitigate the GIL. So probably the most prominent thing is nowadays just replace multi-threading with async IO or replace multi-threading with multi-processing and async IO or just move all CPU intensive workload into siphon because then you can actually release the GIL if possible. Or why should we actually use Python at that level of scale we could just rewrite everything for example rust go whatever the truth is rewriting and also refactoring is actually expensive i mean it takes some time you have two systems in parallel most of the time you have to maintain still the old system while you rewrite it into new language it's very expensive and you normally don't want to do that so the plan was now actually to step to go one step back and say okay maybe we should first verify that is is actually a problem with the global interpreter log and then based on the collected data where we actually prove that it's a problem with the global interpreter log we can start to think about a better solution okay now we should take a look at the game cannot be so complicated right i mean something like import sys get gil stats no doesn't work like that there is sadly no public api yet to acquire such gil statistics from the c-python integrator at the moment okay so how do i now can actually analyze the gil and the nice thing is i'm not the first person who actually had that problem. I'm one of the later person probably. And there are other talks and other related works to that. So for example, there is a nice talk of Dave Baisley on a previous PyCon. It's actually a bit older. It's from 2010, but most of the things are still valid because the GIL doesn't change so often. to understand, okay, how does the GIL actually perform? How often do we have a GIL block contention and so on? And there is also some nice results how we actually modified the CPython interpreter to get results of the CPython interpreter to generate this nice picture to visualize the GIL contention, which is quite nice. The problem is it is actually implemented for CPython 2.6, and our scheduler works with CPython 3.7, so it's not so easy to adapt that. Therefore, we have to look for something else. And then I remembered, ah, there is maybe something in one of the IDs. PyCharm has some nice concurrency view on that. Yes, PyCharm can visualize threads and log contentions in a nice concurrency view, but it actually omits the girl doesn't help me in my case now there's another very interesting tool it's called um gill load which you can attach or which you can integrate in your application and then it will print out statistic regarding the girl in this example i just run an application which is highly bound to the global interpretor log, and we see, okay, yes, I have a gill out of one, but I actually don't have additional information about that. I don't know, okay, which thread is now suffering from that or which thread is holding the gill, how long, and so on. Doesn't help in that case, no. There is actually a very, very interesting project at the moment, PySpy, which is an assembling profiler for Python, written in Rust. But, I mean, from that perspective, it's very nice because we can use Rust to instrument Python and get some statistics. That's not so bad. And it's also quite fast. The problem is, at the moment, it only shows the GIL usage in a percent number. but i just read that there are actually now new features which i actually didn't try it out yet so that it should also provide you additional information regarding the girl but as i had this problem some months ago the feature was not available yet so the typical answer for that is okay i have to build that by myself which is not so great but there's a simple solution for that there is already some framework within cpython to build such type of instrumentation this base is actually system tab system tab is an instrumentation tool for linux which allows you to add certain markers in your applications and at runtime you can attach so-called probes to that markers and the probes will be invoked every time the application hits a certain marker which is quite nice because with that you can actually write a system tab script that will be always called sorry the probe inside of the system tab script will be called every time you for example enter a python function or you exit a python function also there's a very great documentation regarding cpython system tab and dtrace and how you can use it but there are basically two main problems the first problem is most pre-built linux packages are not compiled with the dtrace flag so you don't have access to that markers and the second problem is there are actually no GIL related markers set so you cannot really attach to the GIL related events in the way that you can analyze it. But actually even if I'm not so familiar with C it was not that complicated to add them. So this is the full patch basically to add two markers. At the end I needed three markers so that I now can actually instrument CPython and can add certain probes at these markers and retrieve the timing information of the GIL time. You may ask now okay, why I call actually Python get fretted end? This is a nice feature of system type. You can actually add additional attributes to a marker so that within your system tab script, you can actually access these attributes and use them. And here I now use actually the Python thread indent method to get the idea of the Python thread. Sadly there is no API to get the thread name. Otherwise it would be even more comfortable for me to get an idea which thread is now acquiring the girl. okay if i now compile my special c python version with these markers i can attach a script to it but what type of script do i actually attach to that um therefore um i have an example of that which you can also reuse um this is a system tab script and every probe will be attached to your Python interpreter and every time

Speaker 2 [15:04]

time.

Speaker 1 [15:05]

A thread will now try to claim the GIL, will now invoke the certain probe. Every time a thread acquired, actually, the GIL will call into that script. And every time a thread dropped the global interpreter log will also go into the script. And here, it's a very simple implementation of measuring the time. So, what I do is, every time a thread tries to claim the GIL, we wrote down the time of today in nanoseconds, store them in a hash map with the current thread ID. Every time I acquire the GIL or the thread acquires the GIL, we just store, okay, how long was the wait time? And I store that in a histogram, which is a special system type data type. and the same thing also applies for gilthrop there i also store the time okay how long i actually hold the girl okay now i have the timing information and i cannot use this timing information but i can actually not see the timing information because they are now stored in this strange histogram data type sensor the nice thing is actually we can now visualize that by just printing out all the data from a system type. There are two special probes which will be invoked every time you attach a system type script to a Python interpreter or if you terminate this system type process. And at the termination of the system type process, we can print out what are the stored data inside of the histograms so that I can see for each thread, okay, how long was the wait time, how long was the hold time, and so on, and so on. And now maybe this is a bit abstract and not so easy to follow. Therefore, I would like to show an example how it actually works. So let's take a look on the first experiment, which is a process with two IO-bound threads. and the way how I simulated an IO bound thread is quite simple. I just call time.sleep because time.sleep will actually release the GIL just before the thread went into the sleep state. So we basically just simulate the same process like you would have if you read from a socket or write to a socket and so on. So now I can start that Python process with this super simple but still useful application and at the end and i detach my system tab process from it i get a summary and what i can see now is okay i have three threads one is the main thread the two other threads are my io threads and i have the aggregated numbers for the wait time and the hold time. And overall, I see actually, okay, overall, I just hold the GIL around 0.2% of the runtime. So it looks like my application is not that busy with executing Python instructions. And there's probably nearly no contention because the wait time overall is super low. We cannot change that and introduce another thread in another experiment with a CPU-bound thread. And how do you generate a CPU-bound thread? I could now train some complicated machine learning model or do something else. Or I can just implement a while loop, which is just while true and is racing CPU cycles. Okay, but that works for the moment. And now we can take another look on the results. So, overall, we have now four threads. Surprise, surprise. We have the main thread. Okay. We have the IO thread. Interesting. The wait time is already significantly increased. The hold time is still quite low because we just have to go again over the while loop, change the value of n, and so on. um also the second io thread has the same problem also increased wait time but the cpu thread the cpu thread has actually no no big problem wait time looks quite good whole time okay it's huge and if we take a look on the overall result okay we basically have all the time some thread which is holding the gill so we are running all the time real python instruction because i mean we have to execute the pass command in our cpu spinning thread the nice thing is with the system type histograms can also get a better overview regarding the distribution of the values instead of just aggregates. So what I found quite interesting, and I was totally not aware of that, is that the wait time is actually quite stable. So the wait time is very stable between 4 and 8 milliseconds. And I was a bit confused about that. But overall, what I can say already is that every I.O. thread already suffered just from this one single CPU-bound thread. So what I can say is basically, okay, skill contention already affects my overall application performance. And now I would also like to go a bit more into the detail regarding this 5 milliseconds because it was quite strange to me. I would expect that there are some fluctuations or something like that. But it was very stable all the time. Reproduced it all the time, and I just thought about, where are these 5 milliseconds coming from? And then I learned, also from the talk of Dick Baisley, that there's actually a so-called switch interval within the Python interpreter. And the trick is, of the new global interpreter log, that the switch interval is some kind of a grace period for a thread that would like to acquire the GIL. So if a thread would like to acquire the GIL, he will mark a flag, I would like to have the GIL, and will wait until the GIL is free again. But if this one runs into a timeout, which is actually the switch interval, then it will set another flag where the thread is actually requesting that the current holding thread should please drop the GIL. So that means if I have now a CPU-bound thread that basically all the time is iterating over Python instructions, it will at least, an IO thread, at least wait until the switch interval before there's a chance that this CPU-bound thread who will never release the GIL without any external invocation until the IO thread will actually acquire the GIL. Disclaimer, this don't have to be true because at the end, this drop request will be checked every time you execute a new Python instruction, a new Python operation. that means if you have a bytecode operation that takes much longer than five milliseconds the switch interval will not help you also the same thing applies to external c functions if you call out to an external c function that holds the global interpreter log hopefully the function will come back at some point in time and will release the game okay so much to the theory let's go back into real production i mean now we have some basic rudimentary tool to actually analyze the girl so the plan should be quite straightforward we deploy a new container with the task scheduler with this customized c-python version and SystemTab, we attach SystemTab to the process, collecting all the data, and at the end we have a clear result and insight what's going on. Reality is a bit different. Deploying the container with the customer CPython version was the easiest part. The problem was then to actually find out, okay, how can I actually use SystemTab inside of a Docker container? that's not so easy because at the end what you have to know is that system tab is actually generating a kernel module out of this system tab script and will load this inside of your linux kernel at runtime to collect all that kind of data that means you need a full toolchain with compiler and so on kernel sources and a lot of other stuff that's not so nice and i'm pretty sure every security team will be not so happy about that if you load some custom kernel extension at runtime in your productive environment but somehow it worked out and i had a huge file a huge text file with report and surprise surprise but i found out i actually have a problem with the gill because we use the gill over 80 percent of the time but nearly 300 percent of the time there were threats who just waited for the gill okay that doesn't look so good but at the end I could prove we actually have no problem with the global interpreter lock there is some contention but it also raises a lot of questions it raises the question what is actually this bad thread who holds the GIL so long is it maybe holding the GIL longer than 5ms I actually assume that our process is fully I.O. bound so no thread should actually hold the GIL longer than 5ms and if so then i probably would like to know okay which function is it is that and so on and maybe there are some kind of patterns that we could identify the reality is inside of our task scheduler we have over 30 threads so the text report was not the best way to visualize that and to analyze that problem, and I thought, okay, there must be a better way. So, at the end, I'm actually a big fan of our distributed tracing approach because I like such timelines. I'm not the best person about data visualization, but at least I can understand such types of data visualization. So, the idea was, okay, could we maybe create something like that for the GIL? And the result is, yes, we can, because this is the nice benefit of Python and the Python ecosystem with all this nice data visualization tools that there are tools to generate nice-looking visualizations. So what I did is collecting all the data with SystemType with this magic kernel extension and so on, store them, load them into a Jupyter notebook and then transform some data and do some transformation what else and at the end I have a nice looking visualization with bookie ok I did that I'm not 100% sure how I was able to do that probably it's related with the very nice documentation of all these various tools that's basically now the visualization these are now two seconds of our task scheduler looks huge and also a bit interesting because each red area actually indicates an area where we actually wait for the gill and as it's now some time slice with the increased size of the block it also takes more time so each big red block is not that great but even worse are the blocks which are dark blue because they hold the gear longer than 100 millisecond so i mean this is now um the visualization for for two seconds we can zoom in a bit zoom in a bit zoom in a bit and at the end i saw okay there is one thread with big blue blocks all the time and then i was so used to nice looking visualization so that i didn't open the text report anymore and so on. I just looked at a GDPR notebook and found out, okay, how can I actually create a pie chart? Even you shouldn't use a pie chart, as I learned from various data visualization people. But, at the end, I found out, okay, we waste most of our time with the girl in a thread who is collecting metrics. Which is not that great, as you can imagine, because But yeah, while collecting metrics and crunching some data on and send them over to our observability stack, we just wasted computer resources and so on. Not that nice. But the nice thing is that it actually made it much easier to fix the problem. So because with the various visualization and some timing information, it was quite easy to find out okay which where we actually now waste the global interpreter lock time and the result was we actually waste most of the time in a c extension that is just not releasing the gill because it the c extension is actually using all the time python data therefore c extension has to hold the gill all the time which is not always a thing that you have in mind because most people probably think i use the c extension yeah it will release the gill i have no problem that's not a problem for me i have no no gill problem because i use c extensions they are fast They're super fast. But as we can see here, that's not always the case. But the nice thing is with that, it was quite easy to fix the problem. So we just started to replace the C extension with some other coding, which we anyhow planned for the future. And we just found out, okay, probably we don't need metrics every 10 seconds. It is probably enough to collect metrics every two minutes. and afterwards it was super easy to get better results the results are still not super great i mean we now still wait around 80 percent of the time for the gill which is not good i mean there are things that we can definitely improve but what i would like to emphasize is that with a simple fix and to be honest it would probably was would be totally enough to just change that part in our application which is one config parameter we actually solved our guilt contention but at the beginning we're not aware that we actually have a guilt contention problem we were not aware that where we actually had guilt contention problem so this journey was quite interesting for us to find actually out okay what is now the problem and how can we fix that so there are various things um that i would like to talk more about but i mean we don't have enough time um but one thing i would like to mention is i think there are various additional ideas regarding instrumentation of CPython and regarding observability of CPython. And what I would like to do is actually to open source all the tool set and so on. I mean, within this presentation, all the system tab scripts and so on, they should already be enough to collect the data and to get an overview regarding the global interpreter log of your applications. But what I would actually like to do is to open source all the additional system type scripts and visualization coding. And also what I think would be nice if we could maybe either integrate the additional GIL markers into CPython or maybe there are other ways how we can collect the data. So I had some talks with various people already about that. So there may be some more efficient ways how we could collect the data. And maybe at a later point in time, there could be some nice user-facing API that is actually providing all the required data over a simple Python API, which would be quite nice because, I mean, then it would be possible to integrate it into the various observability stacks, observability tools. You could, for example, integrate it in your logging, in your distributed tracing approach, whatever. if you are interested about the gil or about gil contention gil instrumentation or observability in general then please feel free to reach out to me and thank you very much

Speaker 2 [34:41]

Thank you so much, Christophe. So we have time for questions, so anybody want to ask questions?

Speaker 1 [34:46]

ask questions

Speaker 2 [34:49]

Fuck you.

Speaker 1 [34:50]

oh okay

Speaker 2 [34:53]

Okay, I thought that's it.

Speaker 1 [34:53]

I felt this

Speaker 2 [34:56]

So I have a question. So in the case that you show us, what would be the danger of doing that? Can you think of a case that we maybe should not do the same thing?

Speaker 1 [35:09]

So using system type for instrumenting your application, so you mean what the danger of that is or what is the exact question?

Speaker 2 [35:21]

Yeah, is it like a case that maybe it's not that helpful or maybe we should avoid doing that? Is there any danger of doing it or is it like a good thing that we should always do it?

Speaker 1 [35:33]

I mean, every type of instrumentation comes with a cost. So if you instrument too much and if you collect maybe too often the same metrics, that can hurt. So from that perspective, it is probably not a big problem to just try it out and find out, okay, do I have a gilt contention problem? because if you know that you don't have a guilt contention problem, then you don't have to waste time to think about, okay, how can I now actually solve my guilt contention problem because you don't have the problem. It's the typical don't optimize scenarios when you are not 100% sure that you actually have a problem in that area. So I think everyone should maybe try out if the person thinks, okay, there is probably a performance bottleneck and it could be the global integrated lock of Python.

Speaker 2 [36:35]

Thank you so much. Any questions? Yep, there's one question.

Speaker 1 [36:44]

In a follow-up to that question, actually, did you observe a meaningful overhead to the changes you introduced to test it? So, with the usage of SystemTab, I mean, I use an instrumentation tool which is already well optimized. I mean, it's basically for kernel development. so the overhead of that is quite low and it was able to use that in production and I actually didn't saw any big additional overhead in our application metrics so from that perspective I think it would be fine but from conversations with some Python core developers I already learned okay maybe in this area of the gill it is not so good to add additional system tap markers because they come also with some small overhead even if you don't attach a system tap process to it but i mean that's something you just probably have to measure because i mean it's the same thing it's always the problem with performance if you don't measure it you don't know what is actually going on thank you so in layman's terms i'd like to know how big of a problem it is globally because there's millions of peoples and up until today me included who write python code and never even think of that 75 percent of the time it does something not related to the code that i wrote is it something that most people should consider some people should consider so what i wouldn't like to say is that the gill is a problem because i think most applications actually don't suffer from a gill contention um especially as most um for example c extensions and so on they also release the gill i mean um i'm not a numpy expert but my expectation is numpy is highly optimized in that and it use its own data structure so there should be no need to hold the gill all the time so from that perspective i think most people are probably not affected by that um but i mean sometimes if you if you just suffer from a performance problem and you have no idea um what could be the root cause of that it is probably uh useful to just check it out if it's the gill and i mean with especially the the new tools um for for example um what would i show a pie spy um there we are talking about a single binary that you can just attach to a running process and over there you have a percentage number how much of the time you actually hold the gill. And if this is not 100%, I would just don't do this magic stuff with system type and so on. I would just be, okay, I probably don't have a gill problem. So that's the simple solution. And I mean, there's a lot of work going on in PySpy, so I would highly recommend to check it out.

Speaker 2 [40:09]

So, oh, maybe one last question? Who really want to ask? Okay, yeah, this is the last question.

Speaker 1 [40:18]

Thank you. Thank you for this talk. Are you aware of any other instrumentation libraries like BPF Trace, which is relatively new and was integrated in the mainline kernel where you don't have to have compiled code that you load to instrument? um yeah so maybe that is one problem uh that we actually run enterprise software so we also run enterprise linux distributions so there is some delay um so we actually don't have access to the nice kernel features um like ebf so um but i think that will be probably simplify a lot of that stuff and i don't see any reason why we shouldn't be able to build a similar instrumentation with system as i did with system tab also with ebp for example

Speaker 2 [41:21]

Thank you so much. Thank you, Christophe, for a good talk and also answering so many questions. So what's going to happen next will be we will have a community space for 10 minutes. And then afterwards, because today there's some change in the schedule, so we won't have the keynote talk afterwards. So we will start the licensing talk early, start at 5. And then we will try to have as much licensing talk as we can. And then, so if you are giving a lightning talk, please come back at five. And also, actually, everybody, please come back at five because it's the best session of the conference. So, yeah, I'll see you soon.