CODEWITHSUNDEEP
cperformanceglibgobject
Phillipp
Phillipp

Reputation: 264

GObject g_type_init and g_object_new take hundres of milliseconds

We are using Apache Thrift in an Apache httpd module to inject data from another service into the request. That works fine except some strange performance problems that seem to stem from gobject.

Initialization of the type system and/or the first object takes normally <1ms, but sometimes there is a batch os requests that take much longer (like >100ms).

In the child_init-Handler, the g_type_init() is called to initialize the type system. When the request is read, the objects are created with g_object_new (around 6).

Time of object init is measured with gettimeofday to get the elapsed time for the user. It looks like this:

VhostResult *result = NULL;
struct timeval  tv1, tv2;
gettimeofday(&tv1, NULL);
result = g_object_new (TYPE_VHOST_RESULT, NULL);
gettimeofday(&tv2, NULL);

This problem only occurs in batches. All object inits are under <1ms for a few minutes and then there are ~10 requests in the same second that take 500ms to create the first object, all finishing at the same time.

Please not that the processes are always destroyed after the request so it is always a fresh forked process, which means no memory leaks.

Edit: As suggested, I added measurement with clock() in addition to wall time and it reports 0 for the measured code block.

Edit 2: I looked at the grafana data for the times where these batches of slow inits pop up and iowait is always high. Could something block the processes becuase of iowait or is iowait measuring memory access, too?

Edit 3: The code used for the timining (cpu time) is

  clock_t t = clock();

  result = g_object_newv(TYPE_VHOST_RESULT, 0, NULL);

  t = clock() - t; // stop

  ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "%i %s result init clock %f ms", thepid, r->hostname, ((float)t)/CLOCKS_PER_SEC*1000);

What could be the reason for this?

Upvotes: 1

Views: 411

Answers (1)

ensonic
ensonic

Reputation: 3440

+1 to use clock() or even better clock_getttime().

In addition, if you instantiate object with no parameters you can avoid the varargs overhead by using:

g_object_newv(TYPE_VHOST_RESULT, 0, NULL);

If you see spikes form time to time, one explanation could be the memory subsystem. A (hidden) free() call will cause glibc to consolidate free regions from time to time.

Upvotes: 1

Related Questions