Looping to write the same file takes longer

[Johnxjj]

Hi, I think I have a new trouble again. I need to write some files repeatedly in each loop. But I find that the time to write the file is different each loop. The minimum cost 9s, the maximum reached 38s. This makes me very confused and difficult to receive.
The file1 is a file of size 512B * 300, writing 512B twice in the same position each loop, for a total of 300 times.
The file2 is a file of size 1076B*5, writing 1076B twice in the same position each loop, for a total of 5 times.
The file3 is a file of size 8000B, write 8000B 20 times each loop.
The file4 is a file of size 7276B, write 7276B once each loop.
The file5 is a file of size 574B, writing 574B twice each loop.

The configuration and LOG is as follows：
`uint8_t lfs_read_buf[512];
uint8_t lfs_prog_buf[512];
uint8_t lfs_file_buf[512];
uint64_t lfs_lookahead_buf[32];
struct lfs_config cfg =
{
/* block device operations */
.read = user_provided_block_device_read,
.prog = user_provided_block_device_prog,
.erase = user_provided_block_device_erase,
.sync = user_provided_block_device_sync,

/* block device configuration */															
.read_size        = 16,					       
.prog_size        = 16,					        
.block_size       = 4096*16,				       
.block_count      = 256/16,				 
.block_cycles     = 100,  		                  
.cache_size       = 512,				              
.lookahead_size   = 32, 		                     

.read_buffer      = lfs_read_buf,		          
.prog_buffer      = lfs_prog_buf,		               
.lookahead_buffer = lfs_lookahead_buf,                

};

struct lfs_file_config file_cfg =
{
.buffer = lfs_file_buf,
};
`
The Log :
lfs debug:569: Littelfs Write file1 time: 0.52 S
lfs debug:589: Littelfs Write file2 time: 0.57 S
lfs debug:603: Littelfs Write file3 time: 7.65 S
lfs debug:614: Littelfs Write file4 time: 0.47 S
lfs debug:627: Littelfs Write file5 time: 0.51 S
lfs debug:645: Littelfs Write every Cycle time: 9.74 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 2 ))

lfs debug:569: Littelfs Write file1 time: 0.58 S
lfs debug:589: Littelfs Write file2 time: 0.67 S
lfs debug:603: Littelfs Write file3 time: 7.81 S
lfs debug:614: Littelfs Write file4 time: 0.35 S
lfs debug:627: Littelfs Write file5 time: 0.46 S
lfs debug:645: Littelfs Write every Cycle time: 9.90 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 3 ))

lfs debug:569: Littelfs Write file1 time: 0.67 S
lfs debug:589: Littelfs Write file2 time: 0.75 S
lfs debug:603: Littelfs Write file3 time: 7.97 S
lfs debug:614: Littelfs Write file4 time: 0.47 S
lfs debug:627: Littelfs Write file5 time: 0.56 S
lfs debug:645: Littelfs Write every Cycle time: 10.44 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 4 ))
....................
....................
lfs debug:569: Littelfs Write file1 time: 3.52 S
lfs debug:589: Littelfs Write file2 time: 2.71 S
lfs debug:603: Littelfs Write file3 time: 20.03 S
lfs debug:614: Littelfs Write file4 time: 0.81 S
lfs debug:627: Littelfs Write file5 time: 1.48 S
lfs debug:645: Littelfs Write every Cycle time: 28.57 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 73 ))

lfs debug:569: Littelfs Write file1 time: 4.55 S
lfs debug:589: Littelfs Write file2 time: 1.77 S
lfs debug:603: Littelfs Write file3 time: 30.99 S
lfs debug:614: Littelfs Write file4 time: 0.42 S
lfs debug:627: Littelfs Write file5 time: 0.47 S
lfs debug:645: Littelfs Write every Cycle time: 38.21 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 74 ))

lfs debug:569: Littelfs Write file1 time: 2.55 S
lfs debug:589: Littelfs Write file2 time: 0.73 S
lfs debug:603: Littelfs Write file3 time: 7.34 S
lfs debug:614: Littelfs Write file4 time: 0.33 S
lfs debug:627: Littelfs Write file5 time: 0.49 S
lfs debug:645: Littelfs Write every Cycle time: 11.46 S
lfs debug:552: Cycle_Count. ( Cycle_Count: 75 ))

[Johnxjj]

I have some new test results. I print out all the time spent in the process of opening a file, writing a file, and closing a file. Then i found some strange phenomena. I think these may be associated with #214 .

Now I will describe some of the things that happened in the 2nd, 73rd, and 74th cycles.
the 2nd ：
file1:
lfs debug:401: lfs_file_opencfg time: 32 ms
lfs debug:427: lfs_file_write time: 281 ms
lfs debug:439: lfs_file_close time: 0 ms
lfs debug:579: Littelfs Write file1 time: 0.64 S
file2:
lfs debug:401: lfs_file_opencfg time: 37 ms
lfs debug:427: lfs_file_write time: 275 ms
lfs debug:439: lfs_file_close time: 3 ms
lfs debug:599: Littelfs Write file2 time: 0.75 S
file3:
lfs debug:401: lfs_file_opencfg time: 34 ms
lfs debug:427: lfs_file_write time: 314 ms
lfs debug:439: lfs_file_close time: 6 ms
lfs debug:613: Littelfs Write file3 time: 8.28 S
file4:
lfs debug:401: lfs_file_opencfg time: 41 ms
lfs debug:427: lfs_file_write time: 333 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:624: Littelfs Write file4 time: 0.39 S
file5:
lfs debug:401: lfs_file_opencfg time: 40 ms
lfs debug:427: lfs_file_write time: 192 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:637: Littelfs Write file5 time: 0.51 S
lfs debug:655: Littelfs Write every Cycle time: 10.59 S
...............
the 73rd ：
file1:
lfs debug:401: lfs_file_opencfg time: 494 ms
lfs debug:427: lfs_file_write time: 1224 ms
lfs debug:439: lfs_file_close time: 0 ms
lfs debug:579: Littelfs Write file1 time: 3.52 S
file2:
lfs debug:401: lfs_file_opencfg time: 497 ms
lfs debug:427: lfs_file_write time: 272 ms
lfs debug:439: lfs_file_close time: 75 ms
lfs debug:599: Littelfs Write file2 time: 2.78 S
file3:
lfs debug:401: lfs_file_opencfg time: 499 ms
lfs debug:427: lfs_file_write time: 381 ms
lfs debug:439: lfs_file_close time: 6 ms
lfs debug:613: Littelfs Write file3 time: 20.19 S
file4:
lfs debug:401: lfs_file_opencfg time: 500 ms
lfs debug:427: lfs_file_write time: 312 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:624: Littelfs Write file4 time: 0.83 S
file5:
lfs debug:401: lfs_file_opencfg time: 499 ms
lfs debug:427: lfs_file_write time: 219 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:637: Littelfs Write file5 time: 1.46 S
lfs debug:655: Littelfs Write every Cycle time: 28.81 S

the 74th ：
file1:
lfs debug:401: lfs_file_opencfg time: 498 ms
lfs debug:427: lfs_file_write time: 1255 ms
lfs debug:439: lfs_file_close time: 1 ms
lfs debug:579: Littelfs Write file1 time: 4.62 S
file2:
lfs debug:401: lfs_file_opencfg time: 499 ms
lfs debug:427: lfs_file_write time: 353 ms
lfs debug:439: lfs_file_close time: 41 ms
lfs debug:599: Littelfs Write file2 time: 1.81 S
file3:
lfs debug:401: lfs_file_opencfg time: 503 ms
lfs debug:427: lfs_file_write time: 397 ms
lfs debug:439: lfs_file_close time: 5 ms

lfs debug:401: lfs_file_opencfg time: 503 ms
lfs debug:427: lfs_file_write time: 365 ms
lfs debug:439: lfs_file_close time: 12085 ms //////////////

lfs debug:401: lfs_file_opencfg time: 10 ms
lfs debug:427: lfs_file_write time: 394 ms
lfs debug:439: lfs_file_close time: 6 ms
file4:
lfs debug:401: lfs_file_opencfg time: 10 ms
lfs debug:427: lfs_file_write time: 407 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:624: Littelfs Write file4 time: 0.43 S
file5:
lfs debug:401: lfs_file_opencfg time: 10 ms
lfs debug:427: lfs_file_write time: 280 ms
lfs debug:439: lfs_file_close time: 2 ms
lfs debug:637: Littelfs Write file5 time: 0.59 S
lfs debug:655: Littelfs Write every Cycle time: 38.92 S

[Johnxjj]

The above log is not complete, I only listed the key areas. In the second time, it took 10.59s. Over time, it took 28.81s to the 73rd time, 38.92s to the 74th times, and it took about 10s in the 75th time, and started to accumulate again.
I found that as the number of loops increased, that is, as the file was written, the time to open the file became longer and longer until the 74th reached a maximum of 503 ms. Then, a very unexpected situation occurred, the closing time reached an amazing 12085ms! Then, as if everything is getting better, the time of each cycle starts again from the minimum and gradually increases over time.
In addition, I observed that the closing time in file 2 would cycle between 75ms, 41ms, 6ms, 141ms, and 108ms. The closing time of other files is normal, between a few milliseconds. I haven't specifically tracked this unusual phenomenon, I guess it may be related to file size and storage.

[Johnxjj]

time.txt
I added the log txt. I divided the written file into 300 records. Each record has a size of 512B and is written twice in the same position each time.
The open time is really longer because there are more logs, so there are more traversals. Tn the “Cycle_Count: 267” of log, The exception of close is because the super block is full, you need to do the traversal of the super block log, erase the second super block, and carry the super block.
In addition, in the “Cycle_Count: 267” of log, I found that when 300 records have been written, starting from the first position, a new block will be opened to write this record, and the next 299 records will be copied and written. The 300 records are written repeatedly each time the file is modified, and the result is that it takes a lot of time.
I think a strategy is needed to avoid this, such as creating a new file. Do you have any better suggestions?