Add additional profiling to tile usage.

Add more profiling 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.
This commit is contained in:
Monty 2009-05-26 04:39:10 -04:00 committed by Sven Neumann
parent 2eaa777314
commit ac51a588d6
5 changed files with 252 additions and 18 deletions

View File

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

View File

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

View File

@ -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 <sys/types.h>
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

View File

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

View File

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