Keeps stats about usage time of disk and cpu.

HISTORY

@@ -14,6 +14,8 @@ SnapRAID HISTORY
  * Auto exclude the lock file.
  * Don't prints the 'UUID set' message anymore because it's the normal
    condition for empty disks.
+ * In 'sync' keeps stats about the amount of time spent waiting for
+   each disk and what is spent in CPU computation.
  * In Windows, if the disk doesn't support reading physical offsets,
    allows SnapRAID to continue anyway.
 

TODO

@@ -3,16 +3,11 @@ SnapRAID TODO
 
 This is the list of TODO items for SnapRAID.
 
+/* close the last file in the disk */
+in sync.c
+
 - Next
 
-* Recognize if the content file is older than parity,
-and in case make a full sync after asking for configuration
-with a --force option.
-
-* Measures the time waited in blocking syscall for each disk,
-and prints stats of the disk speeds when the command finish,
-or when it's running.
-
 * In status prints the allocated parity in each data disk.
 In case, also takes into account the extra available space
 in the parity disks.

cmdline/elem.c

@@ -644,6 +644,7 @@ struct snapraid_disk* disk_alloc(const char* name, const char* dir, uint64_t dev
 	pathslash(disk->dir, sizeof(disk->dir));
 
 	disk->device = dev;
+	disk->tick = 0;
 	disk->first_free_block = 0;
 	disk->has_volatile_inodes = 0;
 	disk->has_unreliable_physical = 0;

cmdline/elem.h

@@ -293,6 +293,8 @@ struct snapraid_disk {
 	char dir[PATH_MAX]; /**< Mount point of the disk. It always terminates with /. */
 	uint64_t device; /**< Device identifier. */
 
+	uint64_t tick; /**< Usage time of the disk. */
+
 	/**
 	 * First free searching block.
 	 * Note that it doesn't necessarely point at the first free block,

cmdline/mingw.c

@@ -1370,5 +1370,15 @@ retry:
 	return count;
 }
 
+uint64_t tick(void)
+{
+	LARGE_INTEGER t;
+
+	if (!QueryPerformanceCounter(&t))
+		return 0;
+
+	return t.QuadPart;
+}
+
 #endif
 

cmdline/portable.h

@@ -236,6 +236,14 @@ int filephy(const char* path, struct stat* st, uint64_t* physical);
  */
 int fsinfo(const char* path, int* has_persistent_inode);
 
+/**
+ * Get the tick counter value.
+ *
+ * Note that the frequency is unspecified, becasue the time measure
+ * is meant to be used to compare the ratio between usage times.
+ */
+uint64_t tick(void);
+
 /**
  * Initializes the system.
  */

cmdline/state.c

@@ -84,7 +84,10 @@ void state_init(struct snapraid_state* state)
 	for(l=0;l<LEV_MAX;++l) {
 		state->parity_path[l][0] = 0;
 		state->parity_device[l] = 0;
+		state->tick[l] = 0;
 	}
+	state->tick_cpu = 0;
+	state->tick_last = tick();
 	state->share[0] = 0;
 	state->pool[0] = 0;
 	state->pool_device = 0;
@@ -4309,10 +4312,13 @@ int state_progress(struct snapraid_state* state, block_off_t blockpos, block_off
 		fflush(stdlog);
 	} else {
 		time_t now;
+		tommy_node* i;
+		unsigned l;
 
 		now = time(0);
 
 		if (state->progress_last != now) {
+			uint64_t tick_total;
 			time_t delta = now - state->progress_start - state->progress_subtract;
 
 			printf("%u%%, %u MiB", countpos * 100 / countmax, (unsigned)(countsize / (1024*1024)));
@@ -4321,6 +4327,16 @@ int state_progress(struct snapraid_state* state, block_off_t blockpos, block_off
 				printf(", %u MiB/s", (unsigned)(countsize / (1024*1024) / delta));
 			}
 
+			tick_total = state->tick_cpu;
+			for(i=state->disklist;i!=0;i=i->next) {
+				struct snapraid_disk* disk = i->data;
+				tick_total += disk->tick;
+			}
+			for(l=0;l<state->level;++l)
+				tick_total += state->tick[l];
+			if (tick_total)
+				printf(", CPU %"PRIu64"%%", state->tick_cpu * 100ULL / tick_total);
+
 			if (delta > 5 && countpos > 0) {
 				unsigned m, h;
 				data_off_t to_do = countmax - countpos;
@@ -4352,6 +4368,52 @@ int state_progress(struct snapraid_state* state, block_off_t blockpos, block_off
 	return 0;
 }
 
+void state_usage_print(struct snapraid_state* state)
+{
+	uint64_t tick_total;
+	uint64_t tick_max;
+	tommy_node* i;
+	unsigned l;
+
+	tick_max = 0;
+	tick_total = 0;
+	for(i=state->disklist;i!=0;i=i->next) {
+		struct snapraid_disk* disk = i->data;
+		tick_total += disk->tick;
+		if (disk->tick > tick_max)
+			tick_max = disk->tick;
+	}
+	for(l=0;l<state->level;++l) {
+		tick_total += state->tick[l];
+		if (state->tick[l] > tick_max)
+			tick_max = state->tick[l];
+	}
+
+	if (!tick_total)
+		return;
+
+	printf("Time for disk:");
+	for(i=state->disklist;i!=0;i=i->next) {
+		struct snapraid_disk* disk = i->data;
+		if (disk->tick == tick_max)
+			printf(" %s:", disk->name);
+		else
+			printf(" ");
+		printf("%"PRIu64"%%", disk->tick * 100ULL / tick_total);
+	}
+	printf("\n");
+
+	printf("Time for parity:");
+	for(l=0;l<state->level;++l) {
+		if (state->tick[l] == tick_max)
+			printf(" %s:", lev_config_name(l));
+		else
+			printf(" ");
+		printf("%"PRIu64"%%", state->tick[l] * 100ULL / tick_total);
+	}
+	printf("\n");
+}
+
 void generate_configuration(const char* path)
 {
 	struct snapraid_state state;

cmdline/state.h

@@ -117,6 +117,21 @@ struct snapraid_state {
 	tommy_hashdyn previmportset; /**< Hashtable by prevhash of all the import blocks. Valid only if we are in a rehash state. */
 	tommy_arrayblkof infoarr; /**< Block information array. */
 
+	/**
+	 * Cumulative time used for parity disks.
+	 */
+	uint64_t tick[LEV_MAX];
+
+	/**
+	 * Cumulative time used for computations.
+	 */
+	uint64_t tick_cpu;
+
+	/**
+	 * Last time used for time measure.
+	 */
+	uint64_t tick_last;
+
 	/**
 	 * Required size of the parity file, computed from the loaded state.
 	 *
@@ -251,6 +266,62 @@ void state_progress_stop(struct snapraid_state* state);
  */
 void state_progress_restart(struct snapraid_state* state);
 
+/**
+ * Set the usage time as wasted one not counted.
+ */
+static inline void state_usage_waste(struct snapraid_state* state)
+{
+	uint64_t now = tick();
+
+	state->tick_last = now;
+}
+
+/**
+ * Set the usage time for CPU.
+ */
+static inline void state_usage_cpu(struct snapraid_state* state)
+{
+	uint64_t now = tick();
+
+	/* increment the time spent in computations */
+	state->tick_cpu += now - state->tick_last;
+
+	state->tick_last = now;
+}
+
+/**
+ * Set the usage time for data disk.
+ */
+static inline void state_usage_disk(struct snapraid_state* state, struct snapraid_disk* disk)
+{
+	uint64_t now = tick();
+
+	/* increment the time spent in the data disk */
+	disk->tick += now - state->tick_last;
+
+	state->tick_last = now;
+}
+
+/**
+ * Set the usage time for parity disk.
+ */
+static inline void state_usage_parity(struct snapraid_state* state, unsigned level)
+{
+	uint64_t now = tick();
+
+	assert(level < LEV_MAX);
+
+	/* increment the time spent in the parity disk */
+	state->tick[level] += now - state->tick_last;
+
+	state->tick_last = now;
+}
+
+/**
+ * Prints the stats of the usage time.
+ */
+void state_usage_print(struct snapraid_state* state);
+
 /****************************************************************************/
 /* misc */
 

cmdline/sync.c

@@ -77,6 +77,9 @@ static int state_hash_process(struct snapraid_state* state, block_off_t blocksta
 		}
 	}
 
+	/* drop until now */
+	state_usage_waste(state);
+
 	countsize = 0;
 	countpos = 0;
 	if (state_progress_begin(state, blockstart, blockmax, countmax))
@@ -113,6 +116,9 @@ static int state_hash_process(struct snapraid_state* state, block_off_t blocksta
 			/* if we have to use the old hash */
 			rehash = info_get_rehash(info);
 
+			/* until now is CPU */
+			state_usage_cpu(state);
+
 			/* if the file is different than the current one, close it */
 			if (handle[j].file != 0 && handle[j].file != block_file_get(block)) {
 				/* file we are processing for error reporting */
@@ -212,6 +218,9 @@ static int state_hash_process(struct snapraid_state* state, block_off_t blocksta
 				/* LCOV_EXCL_STOP */
 			}
 
+			/* until now is disk */
+			state_usage_disk(state, disk);
+
 			countsize += read_size;
 
 			/* now compute the hash */
@@ -406,6 +415,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 	autosavemissing = countmax; /* blocks to do */
 	autosavedone = 0; /* blocks done */
 
+	/* drop until now */
+	state_usage_waste(state);
+
 	countsize = 0;
 	countpos = 0;
 	if (state_progress_begin(state, blockstart, blockmax, countmax))
@@ -528,6 +540,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 				continue;
 			}
 
+			/* until now is CPU */
+			state_usage_cpu(state);
+
 			/* if the file is different than the current one, close it */
 			if (handle[j].file != 0 && handle[j].file != block_file_get(block)) {
 				/* file we are processing for error reporting */
@@ -630,6 +645,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 				/* LCOV_EXCL_STOP */
 			}
 
+			/* until now is disk */
+			state_usage_disk(state, disk);
+
 			countsize += read_size;
 
 			/* now compute the hash */
@@ -758,10 +776,14 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 
 			/* if we have something to recover and enough parity */
 			if (something_to_recover && j == failed_count) {
+				/* until now is CPU */
+				state_usage_cpu(state);
+
 				/* read the parity */
 				/* we are sure that parity exists because */
 				/* we have at least one BLK block */
 				for(l=0;l<state->level;++l) {
+
 					ret = parity_read(parity[l], i, buffer[diskmax+l], state->block_size, stdlog);
 					if (ret == -1) {
 						/* LCOV_EXCL_START */
@@ -773,6 +795,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 						goto bail;
 						/* LCOV_EXCL_STOP */
 					}
+
+					/* until now is parity */
+					state_usage_parity(state, l);
 				}
 
 				/* try to fix the data */
@@ -827,6 +852,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 				/* compute the parity */
 				raid_gen(diskmax, state->level, state->block_size, buffer);
 
+				/* until now is CPU */
+				state_usage_cpu(state);
+
 				/* write the parity */
 				for(l=0;l<state->level;++l) {
 					ret = parity_write(parity[l], i, buffer[diskmax+l], state->block_size);
@@ -840,6 +868,9 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 						goto bail;
 						/* LCOV_EXCL_STOP */
 					}
+
+					/* until now is parity */
+					state_usage_parity(state, l);
 				}
 			}
 
@@ -922,11 +953,16 @@ static int state_sync_process(struct snapraid_state* state, struct snapraid_pari
 			state_write(state);
 
 			state_progress_restart(state);
+
+			/* drop until now */
+			state_usage_waste(state);
 		}
 	}
 
 	state_progress_end(state, countpos, countmax, countsize);
 
+	state_usage_print(state);
+
 	if (error || silent_error) {
 		printf("\n");
 		printf("%8u read/write errors\n", error);

cmdline/unix.c

@@ -235,6 +235,38 @@ int fsinfo(const char* path, int* has_persistent_inode)
 	return 0;
 }
 
+uint64_t tick(void)
+{
+#if HAVE_MACH_ABSOLUTE_TIME
+	/* for Mac OS X */
+	return match_absolute_time();
+#elif HAVE_CLOCK_GETTIME && (defined(CLOCK_MONOTONIC) || defined(CLOCK_MONOTONIC_RAW))
+	/* for Linux */
+	struct timespec tv;
+
+	/* nanosecond precision with clock_gettime() */
+#if defined(CLOCK_MONOTONIC_RAW)
+	if (clock_gettime(CLOCK_MONOTONIC_RAW, &tv) != 0) {
+#else
+	if (clock_gettime(CLOCK_MONOTONIC, &tv) != 0) {
+#endif
+		return 0;
+	}
+
+	return tv.tv_sec * 1000000000ULL + tv.tv_nsec;
+#else
+	/* other platforms */
+	struct timeval tv;
+
+	/* microsecond precision with gettimeofday() */
+	if (gettimeofday(&tv, 0) != 0) {
+		return 0;
+	}
+
+	return tv.tv_sec * 1000000ULL + tv.tv_usec;
+#endif
+}
+
 void os_init(void)
 {
 }

configure.ac

@@ -76,6 +76,9 @@ AC_CHECK_FUNCS([ftruncate fallocate fsync access posix_fallocate posix_fadvise])
 AC_CHECK_FUNCS([pread pwrite getc_unlocked ferror_unlocked fnmatch])
 AC_CHECK_FUNCS([futimes futimens futimesat localtime_r])
 AC_CHECK_FUNCS([fstatat flock statfs])
+AC_CHECK_FUNCS([mach_absolute_time])
+AC_SEARCH_LIBS([clock_gettime], [rt])
+AC_CHECK_FUNCS([clock_gettime])
 
 dnl Checks for architecture
 AC_C_BIGENDIAN