strace and hello world

Posted on October 22, 2023

I've recently gotten obsessed with strace which prints all the system calls that a program makes. So, I wanted to see what happens under the covers when you run the rite of passage 'hello world' program, which every beginning programmer starts with!

creating and running the file

I created a file, hello.py:

#!/bin/python/env
print('Hello world!)

Made it executable and ran it:

chmod +x hello.py
strace ./hello.py

This gave 537 lines of output?!? I think that's all from the #!/bin/python/env line which specifies the Python Interpreter. I removed `print('Hello world!') and that number decreased to 515. So, the actual 'Hello world!' has 22 system calls.

The first system call in the trace is:

execve("./hello.py", ["./hello.py"], 0x7ffde15d5c90 /* 100 vars */) = 0

Which I think I understand because we're running hello.py from the shell which spawns a new process.

Glancing at the other commands, I don't understand what's going on (maybe that's another post!)... Today, I'm focused on finding the system calls used when Python's print statement is run. For now, I'm going to ignore the first 515 lines.

hello world system calls

Near the bottom of the strace, things seem more understandable.

stat("./hello.py", {st_mode=S_IFREG|0777, st_size=33, ...}) = 0

But what is S_IFREG? man stat didn't show anything but the system call man page, man 2 stat did!

The man 2 page, says that it's a "regular" file:

 case S_IFREG:  printf("regular file\n");            break;

A few lines down, I see where we read the contents of hello.py:

read(3, "python3\nprint('hello')", 4096) = 22

The return value of read is the number of bytes read.

That makes sense to me because well, we need to read the file at some point if we want to run it or know what's in it! Why is it equal to 22 though? That's less than 33... Counting each character (which is also considered 1 byte), it looks like read read everything after #!/usr/bin/... Interesting, I wonder why that is? (You can run wc -c < filename to count the number of bytes/characters in a file.)

Finally, I see the system call that prints to the screen. Or, described more literally, writes 6 bytes from the buffer (in this case containing 'hello\n') to the stdout file descriptor (which is always 1). On success, write returns the number of bytes written.

write(1, "hello\n", 6)                  = 6

what I learned

1. In Python, most of the system calls for printing hello world are for starting the Python intreprerter.
2. S_IFREG means that the file is a regular file.
3. Programming is neat because you can run tiny, constrained experiments to verify your understanding.
4. strace is cool and there's a LOT I still don't understand. And that's ok! :)

some questions I still have

• What does chmod +x hello.py do? What happens to hello.py to make it executable? I have a vague understanding that the execute bit is set. But what does that mean? Where is it saved?
• What is with all the strace calls when calling the Python interpreter?
• What is a regular file? How does the Operating System know what's 'regular?
• Does a hello world program in C have significantly fewer system calls?
• What is 0x7ffde15d5c90 in execve("./hello.py", ["./hello.py"], 0x7ffde15d5c90 /* 100 vars */) = 0? A quick glance at the man 2 page doesn't help me.
• Why does the call to read leave out the #!/usr/bin/ part of the program?

appendix: the full strace output of print('Hello world!)

stat("./hello.py", {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
openat(AT_FDCWD, "./hello.py", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
ioctl(3, TCGETS, 0x7fffc18bc300)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 0
lseek(3, -22, SEEK_END)                 = 11
lseek(3, 0, SEEK_CUR)                   = 11
read(3, "python3\nprint('hello')", 4096) = 22
lseek(3, 0, SEEK_END)                   = 33
lseek(3, 0, SEEK_CUR)                   = 33
lseek(3, 0, SEEK_SET)                   = 0
lseek(3, 0, SEEK_CUR)                   = 0
fstat(3, {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
read(3, "#!/usr/bin/python3\nprint('hello'"..., 34) = 33
read(3, "", 1)                          = 0
close(3)                                = 0
stat("./hello.py", {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
readlink("./hello.py", 0x7fffc18abd30, 4096) = -1 EINVAL (Invalid argument)
getcwd("/workspaces/programming-experiments", 4096) = 36
lstat("/workspaces/programming-experiments/hello.py", {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
openat(AT_FDCWD, "./hello.py", O_RDONLY) = 3
fcntl(3, F_GETFD)                       = 0
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
ioctl(3, TCGETS, 0x7fffc18bccc0)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 0
fstat(3, {st_mode=S_IFREG|0777, st_size=33, ...}) = 0
read(3, "#!/usr/bin/python3\nprint('hello'"..., 4096) = 33
lseek(3, 0, SEEK_SET)                   = 0
read(3, "#!/usr/bin/python3\nprint('hello'"..., 4096) = 33
read(3, "", 4096)                       = 0
brk(0x1c96000)                          = 0x1c96000
brk(0x1c88000)                          = 0x1c88000
close(3)                                = 0
write(1, "hello\n", 6)                  = 6
rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0825420090}, {sa_handler=0x629f50, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0825420090}, 8) = 0
sigaltstack(NULL, {ss_sp=0x1c38310, ss_flags=0, ss_size=16384}) = 0
sigaltstack({ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}, NULL) = 0
exit_group(0)                           = ?
+++ exited with 0 +++