midgard_config::open_config is slow

[flack]

I recently did some profiling on openpsa requests with Cachegrind and to my surprise, it turned out that the single most expensive function called is usually midgard_config::open_config(). for example, in AJAX requests, where there is not much going on in the framework level (no navgiation rendering, only very simple styling), open_config accounts for more than 80% of the total request time. In normal requests, open_config uses 30 - 50% of the total time.

This was tested in a VM on Ubuntu 13.04 with PHP 5.5.3 with a MySQL database running locally (using gda5). Unfortunately, in Cachegrind, I cannot see what happens inside of open_config(), so I was wondering: Is there any way to find out what is taking so much time? Also, is there any way to speed this up?

[piotras]

midgard_connection::open_config is expensive. It initializes many internal structures (apart from database connection). Do you use httpd server?

[flack]

Yes, I'm running Apache with multiple vhosts. So each vhost has midgard.configuration set, but for some reason, is_connected() always returns false, which is why open_config() gets called from PHP

[flack]

P.S.: I understand that open_config() does a number of things, but I still find this excessive: On Midgard1, if I run the same request, the most expensive thing is loading 77 files with composer autoloader. On Midgard2, open_config() is ten times slower than loading those 77 files. So whatever open_config() does is roughly the equivalent of loading and parsing 770 PHP files?

[piotras]

This is weird. The most expensive part of config_open is parsing schema files, but this should be already done in php extension. Even if it is not(for unknown reason), parsing should be done once per process, because classes are registered in GType system. Some time ago I did some benchmarks and host with Midgard2 connection was able to serve much more connections then the one with Midgard1. Mostly due to vhost configuration in apache. Make sure max request per child is high in vhost. It's a key to keep connection alive as long as possible.

Do you have any warnings or errors in apache's error log? False is_connected() seems bad and it looks like connection hasn't been initialized at all for that vhost. If there's nothing in error log, set debug in MySQL (restart it) and restart apache. MySQL logs should tell anything about any connection attempts. Establishing connection in apache is done during server startup.

[piotras]

Quick look at code makes me feel that is_connected() might be always false in apache environment. Did you check if you are able to query any object when is_connected() returned false?

[flack]

I just checked by calling $qb->count() on midgard_topic. Before open_config(), it returns zero, afterwards 49, so just skipping open_config()won't work. But mgdschema classes are available when is_connected() is false.

If I call QB before open_config(), I get this is Apache's error log:

** (process:12837): CRITICAL **: gda_connection_create_parser: assertion `GDA_IS_CONNECTION (cnc)' failed

** (process:12837): CRITICAL **: gda_connection_statement_execute_select: assertion `GDA_IS_CONNECTION (cnc)' failed

If I call it afterwards, I get nothing

[flack]

Some more stuff I stumbled upon:

• midgard doesn't write anything in mysql log if I don't call open_config(), not even stuff from the querybuilder call
• in /etc/php5/apache2/conf.d/midgard.ini, midgard.http is set to Off. If I set it to On and restart Apache, I get segfaults and can't access the site

[piotras]

OK. midgard.http set to Off explains why there's no connection available. It must be set On for apache httpd.
I am not able to reproduce any segfault with single vhost. Can you try gdb at least?

gdb --args /usr/sbin/apache2 -X
(gdb) run

and when it crashes:

(gdb) bt

And paste backtrace.

[flack]

OK, I've tried that now and get the following:

Program received signal SIGSEGV, Segmentation fault.
0x00007ffff0289407 in xdebug_add_stack_frame (zdata=zdata@entry=0x7fffffffdba0, op_array=0x0, 
    type=type@entry=1) at /tmp/pear/temp/xdebug/xdebug_stack.c:990
990     /tmp/pear/temp/xdebug/xdebug_stack.c: Datei oder Verzeichnis nicht gefunden.
(gdb) bt
#0  0x00007ffff0289407 in xdebug_add_stack_frame (zdata=zdata@entry=0x7fffffffdba0, op_array=0x0, 
    type=type@entry=1) at /tmp/pear/temp/xdebug/xdebug_stack.c:990
#1  0x00007ffff0278a68 in xdebug_execute_internal (current_execute_data=0x7fffffffdba0, 
    fci=0x7fffffffdce0, return_value_used=1) at /tmp/pear/temp/xdebug/xdebug.c:1520
#2  0x00007ffff3afebfe in zend_call_function () from /usr/lib/apache2/modules/libphp5.so
#3  0x00007ffff3b23e95 in zend_call_method () from /usr/lib/apache2/modules/libphp5.so
#4  0x00007fffea9a78df in zm_activate_midgard2 (type=<optimized out>, 
    module_number=<optimized out>) at midgard-php5/midgard.c:604
#5  zm_activate_midgard2 (type=<optimized out>, module_number=<optimized out>)
    at midgard-php5/midgard.c:586
#6  0x00007ffff3b13d70 in zend_activate_modules () from /usr/lib/apache2/modules/libphp5.so
#7  0x00007ffff3aab36a in php_request_startup () from /usr/lib/apache2/modules/libphp5.so
#8  0x00007ffff3bbe87b in ?? () from /usr/lib/apache2/modules/libphp5.so
#9  0x00005555555a9b90 in ap_run_handler ()
#10 0x00005555555a9feb in ap_invoke_handler ()
#11 0x00005555555bfd7a in ap_process_async_request ()
#12 0x00005555555c004f in ap_process_request ()
#13 0x00005555555bc3f5 in ?? ()
#14 0x00005555555b2ef0 in ap_run_process_connection ()
#15 0x00007ffff4487738 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#16 0x00007ffff4487942 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#17 0x00007ffff4488859 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#18 0x000055555558fe9e in ap_run_mpm ()
#19 0x000055555558929a in main ()

When I disable xdebug, the segfault goes away and the site loads normally with midgard.http=On. is_connected() still returns false in this case, but database access works regardless. BTW: The is_connected() check was added as a workaround for another #49, I don't know if this still applies, but I don't have a lighttpd setup for testing right now.

[piotras]

What midgard-php5 tarball did you use?
I created new issue for is_connected() midgardproject/midgard-core#204

[flack]

I'm using latest git master (868ee23)

[flack]

P.S: I don't know if this has anything to do with the recompile I did today or not, but I just noticed that I'm getting segfaults on one of my other vhosts:

Program received signal SIGSEGV, Segmentation fault.
0x00007fffea95c473 in __midgard_query_select_set_property (object=0x555555a58fa0, 
    property_id=<optimized out>, value=0x7fffffffb630, pspec=<optimized out>)
    at src/midgard_query_select.c:1021
1021                            if (config->priv->dbtype == MIDGARD_DB_TYPE_SQLITE)
(gdb) backtrace
#0  0x00007fffea95c473 in __midgard_query_select_set_property (object=0x555555a58fa0, 
    property_id=<optimized out>, value=0x7fffffffb630, pspec=<optimized out>)
    at src/midgard_query_select.c:1021
#1  0x00007fffea6e386c in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#2  0x00007fffea95a2a7 in _midgard_query_executor_constructor (type=93824997545984, 
    n_construct_properties=2, construct_properties=0x555555f7f0a0)
    at src/midgard_query_executor.c:155
#3  0x00007fffea95c347 in _midgard_query_select_constructor (type=93824997545984, 
    n_construct_properties=2, construct_properties=0x555555f7f0a0)
    at src/midgard_query_select.c:947
#4  0x00007fffea6e4ce1 in g_object_newv () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#5  0x00007fffea6e54d0 in g_object_new_valist ()
   from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#6  0x00007fffea6e5804 in g_object_new () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#7  0x00007fffea95ea42 in midgard_query_select_new (mgd=<optimized out>, storage=<optimized out>)
    at src/midgard_query_select.c:51
#8  0x00007fffea983af8 in midgard_core_query_get_object (mgd=mgd@entry=0x555555a65e40, 
    classname=classname@entry=0x7fffdc0fb370 "openpsa_person", 
    object=object@entry=0x7fffffffba10, async=async@entry=0, error=error@entry=0x7fffffffba18, 
    property=<optimized out>) at src/midgard_core_query.c:2506
#9  0x00007fffea9418ef in midgard_object_new (mgd=mgd@entry=0x555555a65e40, 
    name=name@entry=0x7fffdc0fb370 "openpsa_person", value=value@entry=0x555555f78eb0)
    at src/midgard_object.c:2501
#10 0x00007fffeabe8539 in init_php_midgard_object_from_id (objid=<optimized out>, 
    php_classname=0x7fffdc0fb370 "openpsa_person", instance=0x555555f63d60)
    at /home/sonic/workspace/midgard-php5/php_midgard_object.c:66
#11 zif__midgard_php_object_constructor (ht=<optimized out>, return_value=<optimized out>, 
    return_value_ptr=<optimized out>, this_ptr=0x555555f63d60, return_value_used=<optimized out>)
    at /home/sonic/workspace/midgard-php5/php_midgard_object.c:105
#12 0x00007ffff3bb9557 in ?? () from /usr/lib/apache2/modules/libphp5.so
#13 0x00007ffff3b79378 in execute_ex () from /usr/lib/apache2/modules/libphp5.so
#14 0x00007ffff3b0c029 in zend_execute_scripts () from /usr/lib/apache2/modules/libphp5.so
#15 0x00007ffff3aaac3c in php_execute_script () from /usr/lib/apache2/modules/libphp5.so
#16 0x00007ffff3bbc822 in ?? () from /usr/lib/apache2/modules/libphp5.so
#17 0x00005555555a9d40 in ap_run_handler ()
#18 0x00005555555aa34b in ap_invoke_handler ()
#19 0x00005555555c012a in ap_process_async_request ()
#20 0x00005555555c03ff in ap_process_request ()
#21 0x00005555555bc7a5 in ?? ()
#22 0x00005555555b32a0 in ap_run_process_connection ()
#23 0x00007ffff4485738 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#24 0x00007ffff4485942 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#25 0x00007ffff4486859 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#26 0x000055555559003e in ap_run_mpm ()
#27 0x000055555558943a in main ()

This only happens when midgard.http is set to Off, but independently of whether xdebug is enabled or not. It might be a separate issues, but I really couldn't say

[piotras]

This is separate issue.