Date: 2017-03-02 18:45:03 +0100
Last updated: 2017-10-26 14:01:32 +0200
Date: 2017-03-02 18:45:03 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
Simple test which (to me) gives unexplainable profiling output.
-- create 500M integers
-- get 10 of them into a second table
-- make sure we get a linear and easy to read plan
-- measure the time needed to obtain a MAL plan for a simple join (1-2 ms on my machine)
-- trace the same query
Here's the problem, I cannot explain the timings.
Please find in attachment the outputs for EXPLAIN, TRACE, and STETHOSCOPE.
$ mserver5 --version
Date: 2017-03-02 18:45:33 +0100
Created attachment 541
Date: 2017-03-02 18:45:52 +0100
Created attachment 542
Date: 2017-03-02 18:46:15 +0100
Created attachment 543
Date: 2017-03-02 19:00:05 +0100
Both tables are sorted, and I verified that a mergejoin is used.
219usec seem too short for this join, but 2.4 seconds are definitly too long.
Date: 2017-03-02 19:33:00 +0100
Second correction: compilation was not optimized.
Date: 2017-03-02 20:48:58 +0100
You could run the server with the option -d2097152 ( -d$((1<<21)) ) to get algorithm debug output on the server console (standard error). It will print, among other things, the exact time the join operation took. It is calculated at the lowest level, so it won't be any more accurate than that.
When I try your scenario on my machine, I get 491usec in the trace output, and at the same time 475usec on the server console. It also tells me it does a mergejoin_int.
Date: 2017-03-02 20:55:50 +0100
That is good news. The join IS very fast on this large-ish but easy join.
Do you also get more than 2 seconds wall-clock for the entire query though? If so, the question is where the time goes.
Date: 2017-03-02 21:05:52 +0100
Are you using a debug build? In particular, do you have assertions enabled?
Without callgrind, I got about 2.5 seconds wall clock time for the query. Without callgrind and with -d33554432 it took a staggering 3.6 milliseconds.
Date: 2017-03-02 21:13:16 +0100
I didn't do my test correctly. The fast time was the time for the explain.
Date: 2017-03-02 21:21:42 +0100
It's too late for this.
I now put the SQL statements in a script and run it with
If I run mserver without options (debug build, with assertions, not optimized), the select (without TRACE keyword, but after the EXPLAIN), takes 2.6 seconds.
Date: 2017-03-03 12:03:34 +0100
Sjoerd, I can confirm your timings.
Only compiling with --disable-debug --disable-developer --enable-optimize does not change anything, still 2.3 seconds.
Using debug mask 33554432 makes the whole select execute on my machine in 1.2ms and 1.9ms (88usec for the subjoin) without and with trace, respectively.
Now, these are the timings I'd love to have in production :D
Date: 2017-03-03 12:07:23 +0100
What are the risks of not cleaning the freed memory?
Date: 2017-03-03 12:47:19 +0100
I checked the code of GDKfree().
It clarifies that zeroing the to-be-freed memory is actually a debug measure to simplify detection of double-frees. For production builds, this is not needed.
What perhaps is not very clear is that --disable-developer DOES NOT imply --disable-assert. I got <1ms wall-clock time by using these configure switches, and no debug bitmask:
--disable-debug --disable-developer --disable-assert --enable-optimize
Would't you agree that --disable-developer should imply --disable-assert ?
On a different note, is the profiling information on a developer build to be considered wrong or correct? It sure isn't very informative.
Date: 2017-09-05 12:37:14 +0200
I've changed the description of the --enable-developer option. It's orthogonal to the other options, but it should be clearer now what it's for.
Can this report be closed now?
Date: 2017-09-06 09:24:11 +0200
It can be closed, for me. Thanks.
Date: 2017-09-06 09:35:14 +0200
"Fixed" by clarifying the configure option that apparently caused some confusion.
The text was updated successfully, but these errors were encountered: