TT Lab
Get started
Learn Learning paths Courses

Debugging in Practice

What ran out is here, but the error comes from over there

Continue in TT Lab

One-line summary

When a resource runs out, it is not the code that leaked it but the code that needed the resource afterward that blows up. That is why the traceback points to an innocent module, and the investigation ends only with instrumentation.

Why this is needed

"It dies around three in the afternoon" is the classic sentence in a resource exhaustion report. It is fine in the morning, it is not exactly proportional to load, and after a restart it is fine for a while. That last condition is the decisive clue — if a restart fixes it, something is accumulating.

But when you open the log, you see the victim rather than the culprit. It was the session handler that leaked the file descriptors, yet the error comes from the database connection, or from launching a subprocess, or from the place where the log file is opened. The code that leaked the descriptors has already taken its share, and the moment the floor is exposed, the code that requested a resource next fails.

Because of this mismatch, the investigation goes to the wrong place. Seeing the message "sqlite cannot open the database file," you spend hours digging through disks, permissions, and paths. The file is fine and the permissions are right. It is just that the process can no longer open any file at all.

How it works

The skeleton of a resource exhaustion investigation has three parts.

1. Know the limits. Linux sets resource ceilings per process, and in Python you read and write them with the resource module. RLIMIT_NOFILE is the number of descriptors that can be open at once, and RLIMIT_AS is the size of the address space. As getrlimit(2) defines, a limit has two values, soft and hard, and a process can lower the soft one on its own, at or below the hard one. The fact that you can lower it is what the investigation uses — you can create right now the floor you would hit ten hours from now.

2. Count what accumulates. Linux places a /proc/<pid>/fd directory for each process in proc(5) and puts one entry per open descriptor. If you count those entries, you know how many it is holding right now. If you vary the number of requests and measure this value, you get a few points, and if the points lie on a line, the slope is exactly the number leaked per request. A slope of 0 means no leak. This is how you turn a leak from a "feeling" into data.

3. Write the symptom and the cause separately. The error message after hitting the floor tells you only the kind of resource and does not tell you who used it. So in the report you write the two separately — the list of observed symptoms, and the cause found through instrumentation.

한도                무엇을 막나                 바닥났을 때의 얼굴
RLIMIT_NOFILE      열린 파일·소켓 수           OSError errno 24 (EMFILE),
                                               그리고 자원을 쓰는 남의 코드의 오류
RLIMIT_AS          주소 공간 크기               MemoryError (트레이스백이 남는다)
커널 OOM 킬러      머신 전체의 메모리           SIGKILL (트레이스백이 남지 않는다)

The distinction that matters especially on the memory side is the last two lines of this table. An allocation that hits a limit comes up as an exception and leaves a traceback, but when the kernel kills the process, it disappears with SIGKILL and not even a last log line is left. A report that "the log was cut off midway" is therefore itself a clue. You should also note, though, that RLIMIT_AS is a ceiling on the address space and is not the same as actual usage — a region that is only mapped and never touched still takes up address space.

What you see in the field

First, searching for the words of the error message. If you search for "unable to open database file," you get plenty of talk about permissions and paths. All of it is true, but it has nothing to do with this incident. The signal that makes you suspect resource exhaustion is not the message but the pattern — it gets worse as time passes, a restart fixes it, and different modules fail in turn.

Second, drawing a conclusion from a single observation. "There are 900 descriptors right now" says nothing by itself. You have to measure how many there were originally and how it changes as requests increase. Even two points give you a slope.

Third, covering it up by raising the limit. If you raise the limit, the time of death merely moves from three in the afternoon to ten at night. Unless you fix the leaking side, you will certainly meet it again someday. But lowering the limit is very useful as an investigation tool — it cuts a reproduction that would take ten hours down to a few seconds.

Fourth, counting only files. Descriptors are not just files. Sockets, pipes, event notifications, and even what is briefly used when launching a subprocess share the same limit. So a process that has hit the floor is not unable to open files; it is unable to do anything.

What really matters in practice

What you will do in the next lab

You receive a session handler, build a tool that counts open descriptors, and work out the number leaked per request as a slope by varying the number of requests. You lower the limit to bring the floor forward and reproduce it, and record in what face four different things each fail after hitting the floor. On the memory side too, you reproduce it safely with an address-space limit and write down the difference between what is received as an exception and what gets killed, and finally you prove with the same tool that the fixed version's slope is 0.