From b8b41c55bece08db63c58f63b0f589686fe35ac8 Mon Sep 17 00:00:00 2001
From: Andrea Mazzoleni <amadvance@gmail.com>
Date: Wed, 9 Sep 2026 19:21:42 +0200
Subject: [PATCH] Report detailed timing for content write stages

---
 cmdline/state.c  | 33 ++++++++++++++++++++++++++++++++-
 cmdline/stream.c |  5 +++++
 2 files changed, 37 insertions(+), 1 deletion(-)

diff --git a/cmdline/state.c b/cmdline/state.c
index 369372e8..0969c734 100644
--- a/cmdline/state.c
+++ b/cmdline/state.c
@@ -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);
diff --git a/cmdline/stream.c b/cmdline/stream.c
index aadf917a..76498928 100644
--- a/cmdline/stream.c
+++ b/cmdline/stream.c
@@ -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;