Append to file takes a while - please suggest a better design

[krishnak]

I have a general Logging code in ESP devices for programming, I am not trying to Log any sensor data yet.

I am using

  try:
                    with open(self.currentlogfile,'a+') as f:
                        t2 = time.ticks_us()
                        f.write(msg)
                        t3 =time.ticks_us()        
                except Exception as e:
                    print(e)
         

The f.write alone takes 5 ms when the file is empty. This time grows to around 100ms when the file size is 50K, I rotate logs when they reach 50K.

I also looked at code suggested here by Peter

While his code is faster i.e 1.5ms when the file is empty,
but his solution also takes around 80ms when the file has grown, the time measure is just for the

await swriter.awrite('Hello file\n')
Is there a better way to handle this, so that my logging time is kept with in few milliseconds

[davefes]

Just a thought ... I log to ramdisk every minute and every hour update to the wanted log file in flash.

[sosi-deadeye]

Opening a file, takes time and flushing takes also time.
If you don't close the file, writes are much faster.

I tested it with an ESP32 (WROOM, 4 MiB Flash)

The function fast just opens the file and writes in a loop the data to the file.
slow is the same, but after each write, the flush() method is used.
superslow opens the file for each write.

import time


def fast():
    to_write = "Fixed length " * 10 + "\n"
    total_start = time.ticks_ms()
    
    with open("data.txt", "w") as fd:
        for i in range(20):
            t_start = time.ticks_ms()
            fd.write(to_write)
            delta_ms = time.ticks_ms() - t_start
            print(f"Write {i} took {delta_ms:3.2f} ms")

    total_delta = time.ticks_ms() - total_start
    print(f"Total Time: {total_delta:3.2f} ms")
    print()
    read_start = time.ticks_ms()
    data = open("data.txt").read()
    read_delta = time.ticks_ms() - read_start
    print()
    print(f"Reading the whole file tooks {read_delta:3.2f} ms")
    print(f"len: {len(data) / 1024:.1f} KiB")
    print()
    

def slow():
    to_write = "Fixed length " * 10 + "\n"
    total_start = time.ticks_ms()
    
    with open("data.txt", "w") as fd:
        for i in range(20):
            t_start = time.ticks_ms()
            fd.write(to_write)
            fd.flush()
            delta_ms = time.ticks_ms() - t_start
            print(f"Write {i} took {delta_ms:3.2f} ms")

    total_delta = time.ticks_ms() - total_start
    print(f"Total Time: {total_delta:3.2f} ms")
    print()
    read_start = time.ticks_ms()
    data = open("data.txt").read()
    read_delta = time.ticks_ms() - read_start
    print()
    print(f"Reading the whole file tooks {read_delta:3.2f} ms")
    print(f"len: {len(data) / 1024:.1f} KiB")
    print()


def superslow():
    to_write = "Fixed length " * 10 + "\n"
    total_start = time.ticks_ms()
    # creating new empty file
    open("data.txt", "w").close()
    
    for i in range(20):
        
        # opening the file in append mode for
        # each iteration
        with open("data.txt", "a") as fd:
            t_start = time.ticks_ms()
            fd.write(to_write)
            fd.flush()
            delta_ms = time.ticks_ms() - t_start
            print(f"Write {i} took {delta_ms:3.2f} ms")

    total_delta = time.ticks_ms() - total_start
    print(f"Total Time: {total_delta:3.2f} ms")
    print()
    read_start = time.ticks_ms()
    data = open("data.txt").read()
    read_delta = time.ticks_ms() - read_start
    print()
    print(f"Reading the whole file tooks {read_delta:3.2f} ms")
    print(f"len: {len(data) / 1024:.1f} KiB")
    print()


print("Fast")
fast()

print("Slow")
slow()

print("Superslow")
superslow()

The results:

Fast
Write 0 took 103.00 ms
Write 1 took 1.00 ms
Write 2 took 1.00 ms
Write 3 took 1.00 ms
Write 4 took 1.00 ms
Write 5 took 0.00 ms
Write 6 took 1.00 ms
Write 7 took 1.00 ms
Write 8 took 1.00 ms
Write 9 took 1.00 ms
Write 10 took 9.00 ms
Write 11 took 1.00 ms
Write 12 took 1.00 ms
Write 13 took 1.00 ms
Write 14 took 1.00 ms
Write 15 took 1.00 ms
Write 16 took 1.00 ms
Write 17 took 1.00 ms
Write 18 took 1.00 ms
Write 19 took 1.00 ms
Total Time: 170.00 ms


Reading the whole file tooks 10.00 ms
len: 2.6 KiB

Slow
Write 0 took 52.00 ms
Write 1 took 40.00 ms
Write 2 took 40.00 ms
Write 3 took 49.00 ms
Write 4 took 50.00 ms
Write 5 took 50.00 ms
Write 6 took 51.00 ms
Write 7 took 49.00 ms
Write 8 took 49.00 ms
Write 9 took 51.00 ms
Write 10 took 57.00 ms
Write 11 took 69.00 ms
Write 12 took 60.00 ms
Write 13 took 60.00 ms
Write 14 took 59.00 ms
Write 15 took 59.00 ms
Write 16 took 80.00 ms
Write 17 took 79.00 ms
Write 18 took 69.00 ms
Write 19 took 71.00 ms
Total Time: 1179.00 ms


Reading the whole file tooks 11.00 ms
len: 2.6 KiB

Superslow
Write 0 took 45.00 ms
Write 1 took 43.00 ms
Write 2 took 43.00 ms
Write 3 took 42.00 ms
Write 4 took 53.00 ms
Write 5 took 52.00 ms
Write 6 took 52.00 ms
Write 7 took 52.00 ms
Write 8 took 52.00 ms
Write 9 took 62.00 ms
Write 10 took 62.00 ms
Write 11 took 62.00 ms
Write 12 took 62.00 ms
Write 13 took 62.00 ms
Write 14 took 62.00 ms
Write 15 took 61.00 ms
Write 16 took 62.00 ms
Write 17 took 81.00 ms
Write 18 took 71.00 ms
Write 19 took 72.00 ms
Total Time: 1345.00 ms


Reading the whole file tooks 12.00 ms
len: 2.6 KiB

[krishnak]

Thank you for spending your time on my query. What you are suggesting is correct, I have modified my code to just keep the file open. However if you notice I am only talking about the time taken by the write statement not the whole function. It appears that in a+ mode the file cursor moves to the end of file only when the first write occurs not as soon as it is opened, so the first write always takes around 100ms