From 5afae00f495d0055777d1b2d3049ddf0afe145a6 Mon Sep 17 00:00:00 2001 From: Monty Date: Tue, 26 May 2009 04:39:10 -0400 Subject: [PATCH 2/4] Add additional profiling to tile usage in order to analyze efficiency and behavior of the tile cache. Profiling includes run-time indication of idle swapper activity. Also, fixes to original tile profiling code that appears to have bitrotted some; it was no longer tracking changes made to tile memory outside of tile.c. --- app/base/tile-cache.c | 72 ++++++++++++++++++++-- app/base/tile-manager.c | 12 ++++ app/base/tile-private.h | 14 ++++ app/base/tile-swap.c | 158 +++++++++++++++++++++++++++++++++++++++++++++- app/base/tile.c | 14 ++--- 5 files changed, 252 insertions(+), 18 deletions(-) diff --git a/app/base/tile-cache.c b/app/base/tile-cache.c index 6fd47fd..170588b 100644 --- a/app/base/tile-cache.c +++ b/app/base/tile-cache.c @@ -51,6 +51,14 @@ static TileList clean_list = { NULL, NULL }; static TileList dirty_list = { NULL, NULL }; static guint idle_swapper = 0; +#ifdef TILE_PROFILING +extern gulong tile_idle_swapout; +extern gulong tile_total_zorched; +extern gulong tile_total_zorched_swapout; +extern glong tile_total_interactive_sec; +extern glong tile_total_interactive_usec; +extern gint tile_exist_count; +#endif #ifdef ENABLE_MP @@ -154,14 +162,43 @@ tile_cache_insert (Tile *tile) * cache is smaller than the size of a tile in which case * it won't be possible to put it in the cache. */ - while ((cur_cache_size + max_tile_size) > max_cache_size) + +#ifdef TILE_PROFILING + if ((cur_cache_size + tile->size) > max_cache_size) { - if (! tile_cache_zorch_next ()) + GTimeVal now; + GTimeVal later; + g_get_current_time(&now); +#endif + + while ((cur_cache_size + max_tile_size) > max_cache_size) { - g_warning ("cache: unable to find room for a tile"); - goto out; + if (! tile_cache_zorch_next ()) + { + g_warning ("cache: unable to find room for a tile"); + goto out; + } } + +#ifdef TILE_PROFILING + g_get_current_time(&later); + tile_total_interactive_usec += later.tv_usec - now.tv_usec; + tile_total_interactive_sec += later.tv_sec - now.tv_sec; + + if (tile_total_interactive_usec < 0) + { + tile_total_interactive_usec += 1000000; + tile_total_interactive_sec--; + } + + if (tile_total_interactive_usec > 1000000) + { + tile_total_interactive_usec -= 1000000; + tile_total_interactive_sec++; + } + } +#endif cur_cache_size += tile->size; } @@ -186,6 +223,10 @@ tile_cache_insert (Tile *tile) if (! idle_swapper && cur_cache_dirty * 2 > max_cache_size) { + +#ifdef TILE_PROFILING + g_printerr("idle swapper -> running"); +#endif idle_swapper = g_timeout_add_full (G_PRIORITY_LOW, IDLE_SWAPPER_TIMEOUT, tile_idle_preswap, @@ -264,6 +305,16 @@ tile_cache_zorch_next (void) else return FALSE; +#ifdef TILE_PROFILING + tile_total_zorched++; + tile->zorched = TRUE; + if (tile->dirty || tile->swap_offset == -1) + { + tile_total_zorched_swapout++; + tile->zorchout = TRUE; + } +#endif + tile_cache_flush_internal (tile); if (tile->dirty || tile->swap_offset == -1) @@ -275,7 +326,9 @@ tile_cache_zorch_next (void) { g_free (tile->data); tile->data = NULL; - +#ifdef TILE_PROFILING + tile_exist_count--; +#endif return TRUE; } @@ -290,6 +343,9 @@ tile_idle_preswap (gpointer data) if (cur_cache_dirty * 2 < max_cache_size) { +#ifdef TILE_PROFILING + g_printerr("\nidle swapper -> stopped\n"); +#endif idle_swapper = 0; return FALSE; } @@ -298,6 +354,12 @@ tile_idle_preswap (gpointer data) if ((tile = dirty_list.first)) { + +#ifdef TILE_PROFILING + g_printerr("."); + tile_idle_swapout++; +#endif + tile_swap_out (tile); dirty_list.first = tile->next; diff --git a/app/base/tile-manager.c b/app/base/tile-manager.c index b713e97..6e4d1d3 100644 --- a/app/base/tile-manager.c +++ b/app/base/tile-manager.c @@ -34,6 +34,10 @@ static void tile_manager_allocate_tiles (TileManager *tm); +#ifdef TILE_PROFILING +extern gint tile_exist_peak; +extern gint tile_exist_count; +#endif GType gimp_tile_manager_get_type (void) @@ -199,6 +203,11 @@ tile_manager_get (TileManager *tm, new->size = new->ewidth * new->eheight * new->bpp; new->data = g_new (guchar, new->size); +#ifdef TILE_PROFILING + tile_exist_count++; + if (tile_exist_count > tile_exist_peak) + tile_exist_peak = tile_exist_count; +#endif if (tile->rowhint) { @@ -364,6 +373,9 @@ tile_manager_invalidate_tile (TileManager *tm, { g_free (tile->data); tile->data = NULL; +#ifdef TILE_PROFILING + tile_exist_count--; +#endif } if (tile->swap_offset != -1) diff --git a/app/base/tile-private.h b/app/base/tile-private.h index 8021278..d900c03 100644 --- a/app/base/tile-private.h +++ b/app/base/tile-private.h @@ -18,6 +18,9 @@ #ifndef __TILE_PRIVATE_H__ #define __TILE_PRIVATE_H__ +/* Uncomment to enable global counters to profile the tile system. */ +/* #define TILE_PROFILING */ + #include typedef struct _TileLink TileLink; @@ -48,6 +51,17 @@ struct _Tile guint dirty : 1; /* is the tile dirty? has it been modified? */ guint valid : 1; /* is the tile valid? */ +#ifdef TILE_PROFILING + + guint zorched : 1; /* was the tile flushed due to cache pressure + [zorched]? */ + guint zorchout: 1; /* was the tile swapped out due to cache + pressure [zorched]? */ + guint inonce : 1; /* has the tile been swapped in at least once? */ + guint outonce : 1; /* has the tile been swapped out at least once? */ + +#endif + guchar bpp; /* the bytes per pixel (1, 2, 3 or 4) */ gushort ewidth; /* the effective width of the tile */ gushort eheight; /* the effective height of the tile diff --git a/app/base/tile-swap.c b/app/base/tile-swap.c index 1894987..b19d211 100644 --- a/app/base/tile-swap.c +++ b/app/base/tile-swap.c @@ -53,7 +53,6 @@ #include "gimp-intl.h" - typedef enum { SWAP_IN = 1, @@ -116,6 +115,39 @@ static gboolean seek_err_msg = TRUE; static gboolean read_err_msg = TRUE; static gboolean write_err_msg = TRUE; +#ifdef TILE_PROFILING +static gulong tile_total_seek = 0; + +/* how many tiles were swapped out under cache pressure but never + swapped back in? This does not count idle swapped tiles, as those + do not contribute to any perceived load or latency */ +static gulong tile_total_wasted_swapout = 0; + +/* total tile flushes under cache pressure */ +gulong tile_total_zorched = 0; +gulong tile_total_zorched_swapout = 0; +static gulong tile_total_zorched_swapin = 0; + +/* total tiles swapped out to swap file (not total calls to swap out; + this only counts actual flushes to disk) */ +static gulong tile_total_swapout = 0; +static gulong tile_unique_swapout = 0; +gulong tile_idle_swapout = 0; + +/* total tiles swapped in from swap file (not total calls to swap in; + this only counts actual tile reads from disk) */ +static gulong tile_total_swapin = 0; +static gulong tile_unique_swapin = 0; + +/* total dead time spent waiting to read or write */ +static glong tile_total_swapwait_sec = 0; +static glong tile_total_swapwait_usec = 0; + +/* total time spent in tile cache due to cache pressure */ +glong tile_total_interactive_sec = 0; +glong tile_total_interactive_usec = 0; + +#endif #ifdef G_OS_WIN32 @@ -191,11 +223,29 @@ tile_swap_init (const gchar *path) void tile_swap_exit (void) { -#ifdef HINTS_SANITY + +#ifdef TILE_PROFILING extern int tile_exist_peak; - g_printerr ("Tile exist peak was %d Tile structs (%d bytes)", - tile_exist_peak, tile_exist_peak * sizeof(Tile)); + g_printerr ("\n\nPeak Tile usage: %d Tile structs\n\n", + tile_exist_peak); + + g_printerr ("Total tiles swapped out to disk: %lu\n",tile_total_swapout); + g_printerr ("Unique tiles swapped out to disk: %lu\n",tile_unique_swapout); + g_printerr ("Total tiles swapped in from disk: %lu\n",tile_total_swapin); + g_printerr ("Unique tiles swapped in from disk: %lu\n",tile_unique_swapin); + g_printerr ("Tiles swapped out by idle swapper: %lu\n",tile_idle_swapout); + g_printerr ("Total seeks during swapping: %lu\n",tile_total_seek); + g_printerr ("Total time spent in swap: %f seconds\n\n", + tile_total_swapwait_sec+.000001*tile_total_swapwait_usec); + + g_printerr ("Total zorched tiles: %lu\n",tile_total_zorched); + g_printerr ("Total zorched tiles swapped out: %lu\n",tile_total_zorched_swapout); + g_printerr ("Total zorched tiles swapped back in: %lu\n",tile_total_zorched_swapin); + g_printerr ("Total zorched tiles wasted after swapping out: %lu\n",tile_total_wasted_swapout); + g_printerr ("Total interactive swap/cache delay: %f seconds\n\n", + tile_total_interactive_sec+.000001*tile_total_interactive_usec); + #endif if (tile_global_refcount () != 0) @@ -316,14 +366,35 @@ tile_swap_default_in (SwapFile *swap_file, { gint nleft; gint64 offset; +#ifdef TILE_PROFILING + GTimeVal now; + GTimeVal later; +#endif if (tile->data) return; +#ifdef TILE_PROFILING + g_get_current_time(&now); + tile_total_swapin++; + + if (tile->zorched) + tile_total_zorched_swapin++; + + if (!tile->inonce) + tile_unique_swapin++; + + tile->inonce = TRUE; +#endif + if (swap_file->cur_position != tile->swap_offset) { swap_file->cur_position = tile->swap_offset; +#ifdef TILE_PROFILING + tile_total_seek++; +#endif + offset = LARGE_SEEK (swap_file->fd, tile->swap_offset, SEEK_SET); if (offset == -1) { @@ -361,6 +432,42 @@ tile_swap_default_in (SwapFile *swap_file, nleft -= err; } +#ifdef TILE_PROFILING + g_get_current_time(&later); + tile_total_swapwait_usec += later.tv_usec - now.tv_usec; + tile_total_swapwait_sec += later.tv_sec - now.tv_sec; + + if (tile_total_swapwait_usec < 0) + { + tile_total_swapwait_usec += 1000000; + tile_total_swapwait_sec--; + } + + if (tile_total_swapwait_usec > 1000000) + { + tile_total_swapwait_usec -= 1000000; + tile_total_swapwait_sec++; + } + + tile_total_interactive_usec += later.tv_usec - now.tv_usec; + tile_total_interactive_sec += later.tv_sec - now.tv_sec; + + if (tile_total_interactive_usec < 0) + { + tile_total_interactive_usec += 1000000; + tile_total_interactive_sec--; + } + + if (tile_total_interactive_usec > 1000000) + { + tile_total_interactive_usec -= 1000000; + tile_total_interactive_sec++; + } + + tile->zorched = FALSE; + tile->zorchout = FALSE; +#endif + swap_file->cur_position += tile->size; /* Do not delete the swap from the file */ @@ -377,6 +484,17 @@ tile_swap_default_out (SwapFile *swap_file, gint nleft; gint64 offset; gint64 newpos; +#ifdef TILE_PROFILING + GTimeVal now; + GTimeVal later; + g_get_current_time(&now); + tile_total_swapout++; + + if (!tile->outonce) + tile_unique_swapout++; + + tile->outonce = TRUE; +#endif bytes = TILE_WIDTH * TILE_HEIGHT * tile->bpp; @@ -388,6 +506,11 @@ tile_swap_default_out (SwapFile *swap_file, if (swap_file->cur_position != newpos) { + +#ifdef TILE_PROFILING + tile_total_seek++; +#endif + offset = LARGE_SEEK (swap_file->fd, newpos, SEEK_SET); if (offset == -1) @@ -420,6 +543,25 @@ tile_swap_default_out (SwapFile *swap_file, nleft -= err; } +#ifdef TILE_PROFILING + g_get_current_time(&later); + tile_total_swapwait_usec += later.tv_usec - now.tv_usec; + tile_total_swapwait_sec += later.tv_sec - now.tv_sec; + + if (tile_total_swapwait_usec < 0) + { + tile_total_swapwait_usec += 1000000; + tile_total_swapwait_sec--; + } + + if (tile_total_swapwait_usec > 1000000) + { + tile_total_swapwait_usec -= 1000000; + tile_total_swapwait_sec++; + } + +#endif + swap_file->cur_position += tile->size; /* Do NOT free tile->data because we may be pre-swapping. @@ -445,6 +587,14 @@ tile_swap_default_delete (SwapFile *swap_file, if (tile->swap_offset == -1) return; +#ifdef TILE_PROFILING + if (tile->zorchout) + tile_total_wasted_swapout++; + + tile->zorched=FALSE; + tile->zorchout=FALSE; +#endif + start = tile->swap_offset; end = start + TILE_WIDTH * TILE_HEIGHT * tile->bpp; tile->swap_offset = -1; diff --git a/app/base/tile.c b/app/base/tile.c index 0abb3ce..88d3b37 100644 --- a/app/base/tile.c +++ b/app/base/tile.c @@ -32,10 +32,6 @@ /* Uncomment for verbose debugging on copy-on-write logic */ /* #define TILE_DEBUG */ -/* Uncomment to enable global counters to profile the tile system. */ -/* #define TILE_PROFILING */ - - /* This is being used from tile-swap, but just for debugging purposes. */ static gint tile_ref_count = 0; @@ -46,15 +42,14 @@ static gint tile_count = 0; static gint tile_share_count = 0; static gint tile_active_count = 0; -static gint tile_exist_peak = 0; -static gint tile_exist_count = 0; +gint tile_exist_peak = 0; +gint tile_exist_count = 0; #endif static void tile_destroy (Tile *tile); - Tile * tile_new (gint bpp) { @@ -193,6 +188,9 @@ tile_destroy (Tile *tile) { g_free (tile->data); tile->data = NULL; +#ifdef TILE_PROFILING + tile_exist_count--; +#endif } if (tile->rowhint) { @@ -213,8 +211,6 @@ tile_destroy (Tile *tile) #ifdef TILE_PROFILING tile_count--; - - tile_exist_count--; #endif } -- 1.6.3.1