Why Python makes so many sys-calls to read a file?

This weekend, I wanted to build a tool to analyze huge log files using Python, the old-fashioned way: Google, docs, and AI only for research.

At the end, this coding project became a troubleshooting session, that’s life! Join me in this rabbit hole full of CPython code, Linux commands, OS internals, bytes and commits!

The plan was simple: read a big log, measure performance, optimize, repeat. So I started with:

with open("example.log", "r") as file:
	for line in file:
		pass

Let’s start small, an example.log file of 7,690 lines. We run strace on it and boom:

$ du -b example.log 
423607  example.log
$ strace -yy -e trace=read python main.py 2>&1 | grep -c 'read(.*example\.log'
53
# -yy makes strace annotate the file descriptor with the underlying file

The script does 53 read() sys-calls for a 423,607 bytes file, why? In order to improve my script I need answers.

Let’s start by looking at how the method is defined:

open(_file_, _mode='r'_, _buffering=-1_, _encoding=None_, _errors=None_, _newline=None_, _closefd=True_, _opener=None_)

I did not set a buffer size, what’s the default value? From python documentation in open() function:

… the size of the buffer is
buffer_size = max(min(blocksize, 8 MiB), DEFAULT_BUFFER_SIZE)
when the device block size is available. On most systems, the buffer will typically be 128 kilobytes long.

Let’s dig more, the blocksize represents the preferred I/O Block size for the file by the file system. Block sizes are usually multiples of 512 bytes due to the size of hard disk sectors. On Linux the default block size for most file systems is 4,096 bytes.

Using stat command can get the IO Block Python uses:

$ stat example.log 
	File: example.log
	Size: 423607          Blocks: 832        IO Block: 4096   regular file
Device: 0,49    Inode: 454         Links: 1

The 8 MiB (8,388,608 bytes) is simply an upper limit chosen by Python, to avoid creating a huge buffer if the [[Devices#Block device|block device]] returns a very large value.

Finally, DEFAULT_BUFFER_SIZE is a Python constant, see yours using:

>>> import io
>>> print(io.DEFAULT_BUFFER_SIZE, "bytes")
131072 bytes
>>> print(io.DEFAULT_BUFFER_SIZE / 1024, "KiB")
128.0 KiB

In this example, 131,072 bytes should be the chosen size of the buffer. Since, the log file is 423,607 bytes the output should be 4 reads + 1 EOF read, so 5, right? RIGHT?!

$ strace -yy -e trace=read python main.py 2>&1 | grep -c 'read(.*example\.log'
53

Well… no. Because the buffering parameter from open() applies only for BufferedReader and the code is reading line by line from a TextIOWrapper.

The TextIOWrapper uses BufferedReader.read1 which has its own buffering, controlled by an undocumented _CHUNK_SIZE attribute and a hard-coded value of 8192 bytes. Wow, this time I went very deep.

That’s why sys-calls use a fixed buffer size regardless of what Python calculates or what buffering argument is passed toopen().

But why did they choose that value? I could not find an explicit answer in the commit or documentation. On Stack Overflow though, devs mention 8 KiB is a common value that aligns with 4 KiB CPU memory pages and different OS disk blocks. It makes sense from my OS classes at university and it’s almost dinner time, I choose to believe them!

Mystery solved! Now I understand why open() is doing what it is doing. Let’s change it to see some improvement by monkey-patching the buffer size:

with open("example.log", "r") as file:
    file._CHUNK_SIZE = 131072
    for line in file:
        pass

As expected, we achieved the 5 reads and even halved the execution time! Imagine the possibilities if we can set any value we want! For example, in a 10GB log file, with the default 8 KiB buffer ~1.2 million sys-calls are made, but if we increase the buffer to 128 KiB they drop to ~76,000. Over a million sys-calls eliminated!

# Before
$ time strace -yy -e trace=read python main.py 2>&1 | \
	grep 'read(.*example\.log' -c
53
real    0m0.047s
user    0m0.015s
sys     0m0.021s

# After
$ time strace -yy -e trace=read python main.py 2>&1 | \
	grep 'read(.*example\.log' -c
5
real    0m0.023s
user    0m0.007s
sys     0m0.009s

Keep in mind, there are better ways to achieve the reduction of sys-calls, the _CHUNK_SIZE is a private attribute and even though monkey-patching works, it could break between Python versions, so don’t try in production!

In the next iterations of the project, I want to try those cleaner approaches like using bytes mode and reading in chunks. But for now, that concludes my report!

Resources that helped me during the reseach: