Benchmarking CaosDB =================== Benchmarking CaosDB may encompass several distinct areas: How much time is spent in the server’s Java code, how much time is spent inside the SQL backend, are the same costly methods called more than once? This documentation tries to answer some questions connected with these benchmarking aspects and give you the tools to answer your own questions. Before you start ---------------- In order to obtain meaningful results, you should disable caching. MariaDB ~~~~~~~ Set the corresponding variable to 0: ``SET GLOBAL query_cache_type = 0;`` Java Server ~~~~~~~~~~~ In the config: .. code:: cfg CACHE_DISABLE=true Tools for the benchmarking -------------------------- For averaging over many runs of comparable requests and for putting the database into a representative state, Python scripts are used. The scripts can be found in the ``caosdb-dev-tools`` repository, located at https://gitlab.indiscale.com/caosdb/src/caosdb-dev-tools in the folder ``benchmarking``: Python Script ``fill_database.py`` ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ This commandline script is meant for filling the database with enough data to represeny an actual real-life case, it can easily create hundreds of thousands of Entities. The script inserts predefined amounts of randomized Entities into the database, RecordTypes, Properties and Records. Each Record has a random (but with defined average) number of Properties, some of which may be references to other Records which have been inserted before. Actual insertion of the Entities into CaosDB is done in chunks of a defined size. Users can tell the script to store times needed for the insertion of each chunk into a tsv file. Python Script ``measure_execution_time.py`` ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ A somewhat outdated script which executes a given query a number of times and then save statistics about the ``TransactionBenchmark`` readings (see below for more information about the transaction benchmarks) delivered by the server. Python Script ``sql_routine_measurement.py`` ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Simply call ``./sql_routine_measurement.py`` in the scripts directory. An sql file is automatically executed which enables the correct ``performance_schema`` tables. However, the performance_schema of mariadb needs to be enabled. Add ``performance_schema=ON`` to the configuration file of mariadb as it needs to be enabled on start up. This script expects the MariaDB server to be accessible on 127.0.0.1 with the default caosdb user and password (caosdb;random1234). You might consider to increase ``performance_schema_events_transactions_history_long_size``. :: performance_schema_events_transactions_history_long_size=1000000 The performance schema must be enabled (see below). MariaDB General Query Log ~~~~~~~~~~~~~~~~~~~~~~~~~ MariaDB and MySQL have a feature to enable the logging of SQL queries’ times. This logging must be turned on on the SQL server as described in the `upstream documentation `__: Add to the mysql configuration: :: log_output=TABLE general_log or calling .. code:: sql SET GLOBAL log_output = 'TABLE'; SET GLOBAL general_log = 'ON'; In the Docker environment LinkAhead, this can conveniently be done with ``linkahead mysqllog {on,off,store}``. MariaDB Slow Query Log ~~~~~~~~~~~~~~~~~~~~~~ See `slow query log docs `__ MariaDB Performance Schema ~~~~~~~~~~~~~~~~~~~~~~~~~~ The most detailed information on execution times can be acquired using the performance schema. To use it, the ``performance_schema`` setting in the MariaDB server must be enabled(`docs `__, for example by setting this in the config files: :: [mysqld] performance_schema=ON The performance schema provides many different tables in the ``performance_schema``. You can instruct MariaDB to create those tables by setting the appropriate ``instrument`` and ``consumer`` variables. E.g. .. code:: sql update performance_schema.setup_instruments set enabled='YES', timed='YES' WHERE NAME LIKE '%statement%'; update performance_schema.setup_consumers set enabled='YES' WHERE NAME LIKE '%statement%'; This can also be done via the configuration. :: [mysqld] performance_schema=ON performance-schema-instrument='statement/%=ON' performance-schema-consumer-events-statements-history=ON performance-schema-consumer-events-statements-history-long=ON You may want to look at the result of the following commands: .. code:: sql select * from performance_schema.setup_consumers; select * from performance_schema.setup_instruments; Note, that the ``base_settings.sql`` enables appropriate instruments and consumers. Before you start a measurement, you will want to empty the tables. E.g.: .. code:: sql truncate table performance_schema.events_statements_history_long ; The procedure ``reset_stats`` in ``base_settings.sql`` clears the typically used ones. The tables contain many columns. An example to get an informative view is .. code:: sql select left(sql_text,50), left(digest_text,50), ms(timer_wait) from performance_schema.events_statements_history_long order by ms(timer_wait); where the function ``ms`` is defined in ``base_settings.sql``. Or a very useful one: .. code:: sql select left(digest_text,100) as digest,ms(sum_timer_wait) as time_ms, count_star from performance_schema.events_statements_summary_by_digest order by time_ms; Useful SQL configuration with docker ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ In order to allow easy testing and debugging the following is useful when using docker. Change the docker-compose file to include the following for the mariadb service: :: networks: # available on port 3306, host name 'sqldb' - caosnet ports: - 3306:3306 Check it with ``mysql -ucaosdb -prandom1234 -h127.0.0.1 caosdb`` Add the appropriate changes (e.g. ``performance_schema=ON``) to ``profiles/empty/custom/mariadb.conf.d/mariadb.cnf`` (or in the profile folder that you use). Manual Java-side benchmarking ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Benchmarking can be done using the ``TransactionBenchmark`` class (in package ``org.caosdb.server.database.misc``). - Single timings can be added to instances of that class via the ``addBenchmark(object, time)`` method. Multiple benchmarks for the same object (typically just strings) can be averaged. - Benchmarks can be serialized into XML, ``Container`` and ``Query`` objects already use this with their included benchmarks to output benchmarking results. - To work with the benchmarks of often used objects, use these methods: - ``Container.getTransactionBenchmark().addBenchmark()`` - ``Query.addBenchmark()`` To enable transaction benchmarks and disable caching in the server, set these server settings: .. code:: cfg TRANSACTION_BENCHMARK_ENABLED=true CACHE_DISABLE=true Additionally, the server should be started via ``make run-debug`` (instead of ``make run-single``), otherwise the benchmarking will not be active. Notable benchmarks and where to find them ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +----------------------+---------------------------+------------------+ | Name | Where measured | What measured | +======================+===========================+==================+ | ``Retrieve.init`` | transac | transaction/ | | | tion/Transaction.java#135 | Retrieve.java#48 | +----------------------+---------------------------+------------------+ | ``Re | transac | transaction/R | | trieve.transaction`` | tion/Transaction.java#174 | etrieve.java#133 | +----------------------+---------------------------+------------------+ | ``Retriev | transac | transaction/ | | e.post_transaction`` | tion/Transaction.java#182 | Retrieve.java#77 | +----------------------+---------------------------+------------------+ | ``EntityResource.h | resource/transactio | all except XML | | ttpGetInChildClass`` | n/EntityResource.java#118 | generation | +----------------------+---------------------------+------------------+ | ``ExecuteQuery`` | ? | ? | +----------------------+---------------------------+------------------+ | | | | +----------------------+---------------------------+------------------+ External JVM profilers ~~~~~~~~~~~~~~~~~~~~~~ Additionally to the transaction benchmarks, it is possible to benchmark the server execution via external Java profilers. For example, `VisualVM `__ can connect to JVMs running locally or remotely (e.g. in a Docker container). To enable this in LinkAhead’s Docker environment, set .. code:: yaml devel: profiler: true Alternatively, start the server (without docker) with the ``run-debug-single`` make target, it will expose the JMX interface, by default on port 9090. Most profilers, like as VisualVM, only gather cumulative data for call trees, they do not provide complete call graphs (as callgrind/kcachegrind would do). They also do not differentiate between calls with different query strings, as long as the Java process flow is the same (for example, ``FIND Record 1234`` and ``FIND Record A WHICH HAS A Property B WHICH HAS A Property C>100`` would be handled equally). Example settings for VisualVM ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ In the sampler settings, you may want to add these expressions to the blocked packages: ``org.restlet.**, com.mysql.**``. Branches on the call tree which are entirely inside the blacklist, will become leaves. Alternatively, specify a whitelist, for example with ``org.caosdb.server.database.backend.implementation.**``, if you only want to see the time spent for certain MySQL calls. How to set up a representative database --------------------------------------- For reproducible results, it makes sense to start off with an empty database and fill it using the ``fill_database.py`` script, for example like this: .. code:: sh ./fill_database.py -t 500 -p 700 -r 10000 -s 100 --clean The ``--clean`` argument is not strictly necessary when the database was empty before, but it may make sense when there have been previous runs of the command. This example would create 500 RecordTypes, 700 Properties and 10000 Records with randomized properties, everything is inserted in chunks of 100 Entities. How to measure request times ---------------------------- If the execution of the Java components is of interest, the VisualVM profiler should be started and connected to the server before any requests to the server are started. When doing performance tests which are used for detailed analysis, it is important that 1. CaosDB is in a reproducible state, which should be documented 2. all measurements are repeated several times to account for inevitable variance in access (for example file system caching, network variablity etc.) Filling the database ~~~~~~~~~~~~~~~~~~~~ By simply adding the option ``-T logfile.tsv`` to the ``fill_database.py`` command above, the times for inserting the records are stored in a tsv file and can be analyzed later. Obtain statistics about a query ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ To repeat single queries a number of times, ``measure_execution_time.py`` can be used, for example: .. code:: sh ./measure_execution_time.py -n 120 -q "FIND MusicalInstrument WHICH IS REFERENCED BY Analysis" This command executes the query 120 times, additional arguments could even plot the TransactionBenchmark results directly. On method calling order and benchmarked events ---------------------------------------------- - ``Transaction.execute()`` :: Logs benchmarks for events like: - ``INIT`` :: The transaction’s ``init()`` method. - ``PRE_CHECK`` - ``CHECK`` - ``POST_CHECK`` - ``PRE_TRANSACTION`` - ``TRANSACTION`` -> typically calls ``database.backend.transaction.[BackendTransaction].execute()``, which in turn calls, some levels deeper, ``backend.transaction.....execute( t)`` -> see next point - … - ``backend.transaction.[...].execute(transaction)`` :: This method is benchmarked again (via parent class ``BackendTransaction``), this is probably the deepest level of benchmarking currently (Benchmark is logged as e.g. ``...``). It finally calls ``[MySQLTransaction].execute()``. - ``[MySQLTransaction].execute()`` :: This is the deepest backend implementation part, it typically creates a prepared statement and executes it. - Currently not benchmarked separately: - Getting the actual implementation (probably fast?) - Preparing the SQL statement - Executing the SQL statement - Java-side caching What is measured ---------------- For a consistent interpretation, the exact definitions of the measured times are as follows: SQL logs ~~~~~~~~ As per https://mariadb.com/kb/en/general-query-log, the logs store only the time at which the SQL server received a query, not the duration of the query. Possible future enhancements ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - The ``query_response_time`` plugin may be additionally used in the future, see https://mariadb.com/kb/en/query-response-time-plugin Transaction benchmarks ~~~~~~~~~~~~~~~~~~~~~~ Transaction benchmarking manually collects timing information for each transaction. At defined points, different measurements can be made, accumulated and will finally be returned to the client. Benchmark objects may consist of sub benchmarks and have a number of measurement objects, which contain the actual statistics. Because transaction benchmarks must be manually added to the server code, they only monitor those code paths where they are added. On the other hand, their manual nature allows for a more abstracted analysis of performance bottlenecks. Java profiler ~~~~~~~~~~~~~ VisualVM records for each thread the call tree, specifically which methods were called how often and how much time was spent inside these methods. Global requests ~~~~~~~~~~~~~~~ Python scripts may measure the global time needed for the execution of each request. ``fill_database.py`` obtains its numbers this way.