Bash script performance issue and remediation

2024-06-17 921 words 5 mins read

I was looking at writing some output to files. The output did not vary much but the number of lines was huge. It was long time back so I dont remember the context of the requirement but I needed to write few million lines of text. The quickest way to do this was bash so I wrote a simple script that could do this. To my astonishment, I could see the script much more time than expected, so here is how I debugged the issue and fixed it.

Here I have taken a fictitious program to demonstrate the issue and am writing only 500K lines. On my laptop with SSD, here is how much time it takes:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
chmod +x a.sh 
$ time ./a.sh
Done writing 50,000 lines to output.txt

real	0m7.137s
user	0m4.971s
sys	0m2.151s
$ time ./a.sh
Done writing 50,000 lines to output.txt

real	0m7.195s
user	0m5.010s
sys	0m2.170s
$ time ./a.sh
Done writing 50,000 lines to output.txt

real	0m7.222s
user	0m5.090s
sys	0m2.116s

When testing for performance, always run the test at least 3 times to see if there is variation in performance or time taken. As you can see above the script is consistently taking 7.1 to 7.2 seconds. I would have expected a little better results :)

So, lets first check the script ( I used ChatGPT to create this script) and here is the script.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
#!/bin/bash

# Define the output file
output_file="output.txt"

# Define the line to be written
line="This is the line to be written 500,000 times."

# Initialize the counter
counter=0

# Loop to write the line 500,000 times
while [ $counter -lt 500000 ]
do
  echo $line >> $output_file
  ((counter++))
done

echo "Done writing 50,000 lines to $output_file"

Pretty simple and as expected, so what is wrong. How can we improve this.

Lets first try to see what is wrong. I will run the script with strace. If you dont have it installed, you can install it with dnf install strace and then run the script with strace and check the output.

Initially you will see some libraries being opened and loaded and some stuff being done for mapping the process to the memory. We are not interested in those, we want to check what the process is doing, so I will skip some of the messages from the top.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
$ strace  ./a.sh
...Snipped...
openat(AT_FDCWD, "output.txt", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
fcntl(1, F_GETFD)                       = 0
fcntl(1, F_DUPFD, 10)                   = 10
fcntl(1, F_GETFD)                       = 0
fcntl(10, F_SETFD, FD_CLOEXEC)          = 0
dup2(3, 1)                              = 1
close(3)                                = 0
newfstatat(1, "", {st_mode=S_IFREG|0644, st_size=136120725, ...}, AT_EMPTY_PATH) = 0
write(1, "This is the line to be written 5"..., 45) = 45
dup2(10, 1)                             = 1
fcntl(10, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
close(10)                               = 0
...Snipped...

We can see that in the output we see the same pattern repeated, well its expected. However, what is problematic is that the file is opened everytime we are writing to it. On retrospect, this is expected but think about how much time we are wasting because of this. Lets try to optimize this.

So, again, I know that we want to use exec to open a file descriptor and use that to write to file. This will help us avoid doing this. Asked ChatGPT to do this optimization and here is updated script.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
#!/bin/bash

# Define the output file
output_file="output.txt"

# Define the line to be written
line="This is the line to be written 500,000 times."

# Open the file descriptor for writing
exec 3> $output_file

# Loop to write the line 500,000 times
for ((i=0; i<500000; i++))
do
  echo $line >&3
done

# Close the file descriptor
exec 3>&-

echo "Done writing 50,000 lines to $output_file"

Let’s try this.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
$ time ./b.sh
Done writing 50,000 lines to output.txt

real	0m4.702s
user	0m3.489s
sys	0m1.204s
$ time ./b.sh
Done writing 50,000 lines to output.txt

real	0m4.655s
user	0m3.436s
sys	0m1.211s
$ time ./b.sh
Done writing 50,000 lines to output.txt

real	0m4.902s
user	0m3.613s
sys	0m1.280s

This is only taking 50% (about 4.5-4.9 seconds) time compared to first one. This is good improvement. It’s only 500K iterations with small line. Think about doing 50M iterations, that will definately help.

Let’s check this in strace.

After the usual loading of libraries and other usual stuff, we can see the file is opened

1
2
3
$ strace ./b.sh
...Snipped...
openat(AT_FDCWD, "output.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3

After the file is opened, we can only see the following

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
dup2(3, 1)                              = 1
fcntl(3, F_GETFD)                       = 0
newfstatat(1, "", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_EMPTY_PATH) = 0
write(1, "This is the line to be written 5"..., 45) = 45
dup2(10, 1)                             = 1
fcntl(10, F_GETFD)                      = 0x1 (flags FD_CLOEXEC)
close(10)                               = 0
fcntl(1, F_GETFD)                       = 0
fcntl(1, F_DUPFD, 10)                   = 10
fcntl(1, F_GETFD)                       = 0
fcntl(10, F_SETFD, FD_CLOEXEC)          = 0

And you can see there is no more open/close of file for every write.

Hope this helps.


author

Authored By Amit Agarwal

Amit Agarwal, Linux and Photography are my hobbies.Creative Commons Attribution 4.0 International License.

We notice you're using an adblocker. If you like our webite please keep us running by whitelisting this site in your ad blocker. We’re serving quality, related ads only. Thank you!

I've whitelisted your website.

Not now
This website uses cookies to ensure you get the best experience on our website. Learn more Got it