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

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

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;

legacy/evas/src/bin/evas_cserve2_fonts.c

@@ -2,6 +2,10 @@
 # include "config.h"
 #endif
 
+#ifdef DEBUG_LOAD_TIME
+#include <sys/time.h>
+#endif
+
 #ifdef BUILD_FONT_LOADER_EET
 #include <Eet.h>
 #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;
 }
 

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");
 }

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 {