Expected number of requests to do a write

[adriangb]

I'm trying to understand where time goes in writing, which seems to take ~500ms for me even with small files and ~50 commits.

My test code looks as follows:

from time import time
import polars as pl
from deltalake import DeltaTable, write_deltalake


df = pl.DataFrame({
    'a': [1, 2, 3],
    'b': [4, 5, 6],
})

tb = df.to_arrow()

table_uri = 's3://adrian-test-123/test/delta'
storage_options = {
    'AWS_ENDPOINT_URL': 'http://localhost:8000',
    'ALLOW_HTTP': 'true',
    "AWS_ACCESS_KEY_ID": "...",
    "AWS_SECRET_ACCESS_KEY" : "...",
    "AWS_S3_ALLOW_UNSAFE_RENAME": "true",
}
write_deltalake(table_uri, tb, engine='rust', mode='append', storage_options=storage_options)

dt = DeltaTable(table_uri, storage_options=storage_options, log_buffer_size=1024 * 1024)
write_deltalake(dt, tb, engine='rust', mode='append', storage_options=storage_options)

# output below starts here
start = time()
write_deltalake(dt, tb, engine='rust', mode='append', storage_options=storage_options)
end = time()
print(f'Elapsed: {end - start:.2f}s')

I'm running a proxy on localhost:8000 so that I can see every request made. For only the last write (the one that's timed) I see:

GET http://localhost:8000/adrian-test-123?list-type=2&prefix=test%2Fdelta%2F_delta_log%2F&start-after=test%2Fdelta%2F_delta_log%2F00000000000000000049 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/_last_checkpoint 
GET http://localhost:8000/adrian-test-123?list-type=2&prefix=test%2Fdelta%2F_delta_log%2F&start-after=test%2Fdelta%2F_delta_log%2F00000000000000000000 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000048.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000047.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000045.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000036.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000026.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000016.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000046.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000039.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000034.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000042.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000025.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000020.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000015.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000044.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000030.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000043.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000038.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000032.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000033.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000024.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000021.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000019.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000018.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000041.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000010.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000009.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000040.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000037.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000028.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000035.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000008.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000031.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000013.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000022.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000029.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000027.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000007.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000011.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000023.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000017.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000014.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000012.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000006.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000005.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000004.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000003.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000001.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000002.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000000.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000048.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000046.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000045.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000047.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000044.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000043.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000042.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000041.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000040.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000039.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000038.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000037.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000036.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000035.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000034.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000033.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000032.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000031.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000030.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000029.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000028.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000027.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000025.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000026.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000024.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000023.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000022.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000021.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000020.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000019.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000018.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000017.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000016.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000015.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000014.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000013.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000012.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000011.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000010.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000009.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000008.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000007.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000006.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000005.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000004.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000003.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000002.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000001.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000000.json 
GET http://localhost:8000/adrian-test-123/test/delta/part-00001-99a7dda0-022c-462e-b4c3-eb914f4b334e-c000.snappy.parquet bytes=927-934
GET http://localhost:8000/adrian-test-123/test/delta/part-00001-99a7dda0-022c-462e-b4c3-eb914f4b334e-c000.snappy.parquet bytes=407-926
PUT http://localhost:8000/adrian-test-123/test/delta/part-00001-03267522-c90b-41a7-8f78-db4111138ab0-c000.snappy.parquet 
PUT http://localhost:8000/adrian-test-123/test/delta/_delta_log/_commit_64240e63-46b8-4e7e-8f4e-52da590672a0.json.tmp 
PUT http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000049.json 
DELETE http://localhost:8000/adrian-test-123/test/delta/_delta_log/_commit_64240e63-46b8-4e7e-8f4e-52da590672a0.json.tmp 
GET http://localhost:8000/adrian-test-123?list-type=2&prefix=test%2Fdelta%2F_delta_log%2F&start-after=test%2Fdelta%2F_delta_log%2F00000000000000000049 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000049.json 
GET http://localhost:8000/adrian-test-123/test/delta/_delta_log/00000000000000000049.json

That's a surprising amount of requests. I don't understand why it's necessary to re-read the entire commit history: it should be up to date, at most a single list operation should confirm that. I also don't understand why it's reading data from parquet files before writing.

All in all I would have thought that only 4 or 5 requests would be needed:

1. Write out the data to a parquet files.
2. Write a temp file for the commit.
3. List _delta_log to get the last commit id.
4. Do a copy on the temp file to the final commit name (retry if failed due to existing / concurrent writers, not applicable here).
5. Delete the temp file (optional? could happen async?).

Am I misunderstanding the Delta Lake protocol? Should I be using something lower-level?

[ion-elgreco]

@adriangb there are many reasons but I'll try to give a couple examples:

• The protocol has changed somewhere in commit 0003. Min writer version is now at 3. We can only know which writer version is minimally required by looking at all the commits. So you cannot just write, without knowing if you are allowed to write to the table because the writer you are using might not support all the required features and protocol versions
• Since it has to read all the log files, you can reduce the amount of GET requests by creating checkpoints. I introduced a change in 0.17.0 that will automatically create checkpoints as part of the post commit. You can adjust this upon table creation by doing configuration = {"delta.checkpointInterval": "10"}
• It always does a get request on _last_checkpoint, to know if a parquet checkpoint exists or not, and if so which one is the latest, so that it can read the checkpoint and then the commits that came after it.

[adriangb]

Also:

2024-04-24T21:39:35.682099+00:00 GET http://localhost:9000/adrian-test-123/test/delta/part-00001-38efb4db-de16-4118-8009-a15256f4abf5-c000.snappy.parquet bytes=927-934
2024-04-24T21:39:35.727437+00:00 GET http://localhost:9000/adrian-test-123/test/delta/part-00001-38efb4db-de16-4118-8009-a15256f4abf5-c000.snappy.parquet bytes=407-926
2024-04-24T21:39:35.769405+00:00 PUT http://localhost:9000/adrian-test-123/test/delta/part-00001-e1758823-ad9c-4d13-9ff5-be782a9e3df8-c000.snappy.parquet 

Why would it need to read form the table data just to append?

[ion-elgreco]

@adriangb thanks for the logs, indeed a couple odd things:

• all logs are read every time
• all logs are read twice within one action
• fetches bytes from the latest written parquet file

[ion-elgreco]

@adriangb do you mind creating this into an issue? Then we can have a broader audience looking at it.

[ion-elgreco]

Right... I think I know why we have this : P, instead of reusing the table state in write_to_deltalake. We are reinstaniating it.. I am gonna try to build something real quick! Are you up for testing that later today?

[ion-elgreco]

@adriangb can you build this one locally and try it out: #2453