Report detailed timing for content write stages

This commit is contained in:
Andrea Mazzoleni 2026-09-09 19:21:42 +02:00
parent fde8de1641
commit b8b41c55be
2 changed files with 37 additions and 1 deletions

View file

@ -4525,6 +4525,10 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
block_off_t count_rehash;
block_off_t count_unsynced;
block_off_t count_unscrubbed;
uint64_t stage_start;
uint64_t now;
stage_start = os_tick_ms();
/* blocks of all array */
blockmax = parity_allocated_size(state);
@ -4614,6 +4618,10 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
}
}
now = os_tick_ms();
msg_progress("Prepared state in %" PRIu64 " ms\n", now - stage_start);
stage_start = now;
#if HAVE_MT_WRITE
/* start all writing threads */
first = 1;
@ -4693,6 +4701,10 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
/* LCOV_EXCL_STOP */
}
now = os_tick_ms();
msg_progress("Serialized and wrote content in %" PRIu64 " ms\n", now - stage_start);
stage_start = now;
/*
* All temporary content files of this publication use the same modification time.
* SnapRAID guarantees that two state_write() publications cannot occur in the
@ -4778,6 +4790,8 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
i = i->next;
}
msg_progress("Made content files durable in %" PRIu64 " ms\n", os_tick_ms() - stage_start);
#else
/* count the content files */
count_content = 0;
@ -4848,6 +4862,10 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
/* LCOV_EXCL_STOP */
}
now = os_tick_ms();
msg_progress("Serialized and wrote content in %" PRIu64 " ms\n", now - stage_start);
stage_start = now;
/*
* All temporary content files of this publication use the same modification time.
* SnapRAID guarantees that two state_write() publications cannot occur in the
@ -4889,6 +4907,8 @@ static void state_write_content(struct snapraid_state* state, uint32_t* out_crc)
/* LCOV_EXCL_STOP */
}
msg_progress("Made content files durable in %" PRIu64 " ms\n", os_tick_ms() - stage_start);
crc = context->crc;
count_file = context->count_file;
count_hardlink = context->count_hardlink;
@ -5178,7 +5198,7 @@ static void* state_verify_thread(void* arg)
/* LCOV_EXCL_STOP */
}
msg_progress("Verified %s in %" PRIu64 " seconds\n", content->content, (os_tick_ms() - start) / 1000);
msg_progress("Verified %s in %" PRIu64 " ms\n", content->content, os_tick_ms() - start);
return 0;
}
@ -5497,18 +5517,29 @@ void state_write(struct snapraid_state* state)
{
uint32_t crc;
time_t now;
uint64_t start;
uint64_t stage_start;
start = os_tick_ms();
stage_start = start;
/* verify that all persistent values are serializable */
state_write_check(state);
msg_progress("Validated state in %" PRIu64 " ms\n", os_tick_ms() - stage_start);
/* write all the content files */
state_write_content(state, &crc);
/* verify the just written files */
stage_start = os_tick_ms();
state_verify_content(state, crc);
msg_progress("Verified all content files in %" PRIu64 " ms\n", os_tick_ms() - stage_start);
/* rename the new files, over the old ones */
stage_start = os_tick_ms();
state_rename_content(state);
msg_progress("Published content files in %" PRIu64 " ms\n", os_tick_ms() - stage_start);
msg_progress("State write completed in %" PRIu64 " ms\n", os_tick_ms() - start);
/* log the write time of the content file */
now = time(0);

View file

@ -817,6 +817,9 @@ int ssync(STREAM* s)
for (i = 0; i < s->handle_size; ++i) {
int ret;
uint64_t start;
start = os_tick_ms();
/*
* On macOS, standard fsync() only pushes data from kernel buffers to the
@ -837,6 +840,8 @@ int ssync(STREAM* s)
return -1;
/* LCOV_EXCL_STOP */
}
msg_progress("Synced %s in %" PRIu64 " ms\n", s->handle[i].path, os_tick_ms() - start);
}
return 0;