Expected number of requests to do a write #2448

adriangb · 2024-04-24T06:51:16Z

adriangb
Apr 24, 2024

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:

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

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

ion-elgreco · 2024-04-24T07:04:39Z

ion-elgreco
Apr 24, 2024
Collaborator

@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.

21 replies

adriangb Apr 24, 2024
Author

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 Apr 25, 2024
Collaborator

@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 Apr 25, 2024
Collaborator

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

ion-elgreco Apr 25, 2024
Collaborator

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 Apr 25, 2024
Collaborator

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Expected number of requests to do a write #2448

Uh oh!

{{title}}

Uh oh!

Replies: 1 comment 21 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Expected number of requests to do a write #2448

Uh oh!

adriangb Apr 24, 2024

Replies: 1 comment · 21 replies

Uh oh!

Uh oh!

ion-elgreco Apr 24, 2024 Collaborator

Uh oh!

adriangb Apr 24, 2024 Author

Uh oh!

ion-elgreco Apr 25, 2024 Collaborator

Uh oh!

ion-elgreco Apr 25, 2024 Collaborator

Uh oh!

Uh oh!

ion-elgreco Apr 25, 2024 Collaborator

Uh oh!

ion-elgreco Apr 25, 2024 Collaborator

adriangb
Apr 24, 2024

Replies: 1 comment 21 replies

ion-elgreco
Apr 24, 2024
Collaborator

adriangb Apr 24, 2024
Author

ion-elgreco Apr 25, 2024
Collaborator

ion-elgreco Apr 25, 2024
Collaborator

ion-elgreco Apr 25, 2024
Collaborator

ion-elgreco Apr 25, 2024
Collaborator