From 8ef623d3b50cc0551fc054d877c5973b4fda180e Mon Sep 17 00:00:00 2001 From: Rafael Antognolli Date: Thu, 5 Jul 2012 18:42:22 +0000 Subject: [PATCH] evas/cserve2: The slave should measure the time spent loading glyphs. Instead of measuring the time spent by the server between asking and receiving the glyphs rendered, we measure now the time spent by the slave to load the glyph, and then to render it, and then we report this time to the server. SVN revision: 73373 --- legacy/evas/src/bin/evas_cserve2.h | 3 ++ legacy/evas/src/bin/evas_cserve2_cache.c | 26 ++++++----- legacy/evas/src/bin/evas_cserve2_fonts.c | 56 +++++++++++++++++++++++- legacy/evas/src/bin/evas_cserve2_usage.c | 3 ++ legacy/evas/src/lib/cserve2/evas_cs2.h | 3 ++ 5 files changed, 80 insertions(+), 11 deletions(-) diff --git a/legacy/evas/src/bin/evas_cserve2.h b/legacy/evas/src/bin/evas_cserve2.h index 91c6999a47..855f1f2c10 100644 --- a/legacy/evas/src/bin/evas_cserve2.h +++ b/legacy/evas/src/bin/evas_cserve2.h @@ -176,6 +176,9 @@ typedef struct _Slave_Msg_Font_Cache Slave_Msg_Font_Cache; struct _Slave_Msg_Font_Glyphs_Loaded { unsigned int ncaches; + unsigned int gl_load_time; + unsigned int gl_render_time; + unsigned int gl_slave_time; Slave_Msg_Font_Cache **caches; }; diff --git a/legacy/evas/src/bin/evas_cserve2_cache.c b/legacy/evas/src/bin/evas_cserve2_cache.c index 7704764d16..ddabd50273 100644 --- a/legacy/evas/src/bin/evas_cserve2_cache.c +++ b/legacy/evas/src/bin/evas_cserve2_cache.c @@ -116,9 +116,12 @@ struct _Font_Entry { Font_Cache *last_cache; Eina_Bool unused : 1; #ifdef DEBUG_LOAD_TIME - struct timeval load_start; - struct timeval load_finish; + struct timeval rstart; // start of the glyphs load request + struct timeval rfinish; // finish of the glyphs load request + int gl_request_time; // time spent to process glyph requests int gl_load_time; + int gl_render_time; + int gl_slave_time; int gl_saved_time; #endif }; @@ -1659,7 +1662,10 @@ _glyphs_load_request_build(void *data, int *size __UNUSED__) Font_Entry *fe = req->fe; Font_Cache *fc; +#ifdef DEBUG_LOAD_TIME + gettimeofday(&fe->rstart, NULL); _glyphs_load_request_prepare(req); +#endif msg = calloc(1, sizeof(*msg)); @@ -1679,10 +1685,6 @@ _glyphs_load_request_build(void *data, int *size __UNUSED__) msg->cache.nglyphs = fc->nglyphs; } -#ifdef DEBUG_LOAD_TIME - gettimeofday(&fe->load_start, NULL); -#endif - return msg; } @@ -1753,10 +1755,11 @@ _glyphs_load_request_response(Client *client __UNUSED__, void *data, void *resp, } #ifdef DEBUG_LOAD_TIME - int load_time; - gettimeofday(&fe->load_finish, NULL); - load_time = _timeval_sub(&fe->load_finish, &fe->load_start); - fe->gl_load_time += load_time; + gettimeofday(&fe->rfinish, NULL); + fe->gl_request_time += _timeval_sub(&fe->rfinish, &fe->rstart); + fe->gl_load_time += msg->gl_load_time; + fe->gl_render_time += msg->gl_render_time; + fe->gl_slave_time += msg->gl_slave_time; #endif _glyphs_loaded_send(req, rid); @@ -1815,7 +1818,10 @@ _font_entry_stats_cb(const Eina_Hash *hash __UNUSED__, const void *key __UNUSED_ // accounting glyphs load time msg->fonts.glyphs_load_time += fe->gl_load_time; + msg->fonts.glyphs_render_time += fe->gl_render_time; msg->fonts.glyphs_saved_time += fe->gl_saved_time; + msg->fonts.glyphs_request_time += fe->gl_request_time; + msg->fonts.glyphs_slave_time += fe->gl_slave_time; #endif return EINA_TRUE; diff --git a/legacy/evas/src/bin/evas_cserve2_fonts.c b/legacy/evas/src/bin/evas_cserve2_fonts.c index 3a1cff54eb..08ed4ae1fd 100644 --- a/legacy/evas/src/bin/evas_cserve2_fonts.c +++ b/legacy/evas/src/bin/evas_cserve2_fonts.c @@ -2,6 +2,10 @@ # include "config.h" #endif +#ifdef DEBUG_LOAD_TIME +#include +#endif + #ifdef BUILD_FONT_LOADER_EET #include #endif @@ -434,6 +438,22 @@ _font_slave_int_shm_calculate(Font_Info *fi, unsigned int hint) return size; } +#ifdef DEBUG_LOAD_TIME +static int +_timeval_sub(const struct timeval *tv2, const struct timeval *tv1) +{ + int t1, t2; + + t1 = tv1->tv_usec + tv1->tv_sec * 1000000; + t2 = tv2->tv_usec + tv2->tv_sec * 1000000; + + if (t2 > t1) + return t2 - t1; + + return 0; +} +#endif + static Slave_Msg_Font_Glyphs_Loaded * _font_slave_glyphs_load(const void *cmddata, void *data __UNUSED__) { @@ -442,11 +462,21 @@ _font_slave_glyphs_load(const void *cmddata, void *data __UNUSED__) Font_Info *fi; unsigned int i; unsigned int total_glyphs; +#ifdef DEBUG_LOAD_TIME + unsigned int gl_load_time = 0; + unsigned int gl_render_time = 0; + struct timeval tv_start, tv_end; + struct timeval rstart, rfinish; +#endif Eina_List *caches = NULL; Slave_Msg_Font_Cache *c = NULL; fi = msg->font.ftdata2; +#ifdef DEBUG_LOAD_TIME + gettimeofday(&rstart, NULL); +#endif + _font_slave_size_use(fi); if (msg->cache.shm) @@ -484,8 +514,24 @@ _font_slave_glyphs_load(const void *cmddata, void *data __UNUSED__) total_glyphs = 0; } +#ifdef DEBUG_LOAD_TIME + gettimeofday(&tv_start, NULL); +#endif if (_font_slave_glyph_load(fi, msg->glyphs.glyphs[i], msg->font.hint)) - r = _font_slave_glyph_render(fi, c, msg->glyphs.glyphs[i]); + { +#ifdef DEBUG_LOAD_TIME + gettimeofday(&tv_end, NULL); + gl_load_time += _timeval_sub(&tv_end, &tv_start); + // copy the time that we got here to be used as start of render + tv_start.tv_sec = tv_end.tv_sec; + tv_start.tv_usec = tv_end.tv_usec; +#endif + r = _font_slave_glyph_render(fi, c, msg->glyphs.glyphs[i]); +#ifdef DEBUG_LOAD_TIME + gettimeofday(&tv_end, NULL); + gl_render_time += _timeval_sub(&tv_end, &tv_start); +#endif + } if (!r) // SHM is full { fi->shmsize = _font_slave_int_shm_prev_calculate @@ -506,6 +552,14 @@ _font_slave_glyphs_load(const void *cmddata, void *data __UNUSED__) EINA_LIST_FREE(caches, c) response->caches[i++] = c; +#ifdef DEBUG_LOAD_TIME + response->gl_load_time = gl_load_time; + response->gl_render_time = gl_render_time; + + gettimeofday(&rfinish, NULL); + response->gl_slave_time = _timeval_sub(&rfinish, &rstart); +#endif + return response; } diff --git a/legacy/evas/src/bin/evas_cserve2_usage.c b/legacy/evas/src/bin/evas_cserve2_usage.c index e8307e3f6e..853e63345d 100644 --- a/legacy/evas/src/bin/evas_cserve2_usage.c +++ b/legacy/evas/src/bin/evas_cserve2_usage.c @@ -215,7 +215,10 @@ _usage_msg_read(void) printf("Fonts used load time: %dus\n", msg->fonts.fonts_used_load_time); printf("Fonts used saved time: %dus\n", msg->fonts.fonts_used_saved_time); printf("Glyphs load time: %dus\n", msg->fonts.glyphs_load_time); + printf("Glyphs render time: %dus\n", msg->fonts.glyphs_render_time); printf("Glyphs saved time: %dus\n", msg->fonts.glyphs_saved_time); + printf("Glyphs request time: %dus\n", msg->fonts.glyphs_request_time); + printf("Glyphs slave time: %dus\n", msg->fonts.glyphs_slave_time); printf("\n"); } diff --git a/legacy/evas/src/lib/cserve2/evas_cs2.h b/legacy/evas/src/lib/cserve2/evas_cs2.h index 938ea5f6cc..c44ddc5241 100644 --- a/legacy/evas/src/lib/cserve2/evas_cs2.h +++ b/legacy/evas/src/lib/cserve2/evas_cs2.h @@ -210,7 +210,10 @@ struct _Msg_Stats { * really used, i.e. fonts that have glyphs * rendered */ int fonts_used_saved_time; + int glyphs_request_time; /* time spent waiting for glyph requests */ int glyphs_load_time; /* total time spent loading glyphs */ + int glyphs_render_time; /* total time spent rendering glyphs */ + int glyphs_slave_time; /* total time spent on the slave processing glyph load requests */ int glyphs_saved_time; /* total time spent loading glyphs */ } fonts; struct {