Help! My SELECT is slow!
Now that the first BW systems were migrated to SAP HANA, I believe there will be some demand for understanding what is happening inside the database. I am an Oracle DBA. On Oracle, there were these dreaded "db_file_sequential_read" events slowing down your queries, so preventing physical reads was mostly the way to go. With HANA, things look quite different. All we have is CPU time and memory consumption. (OK, for BW data loads there is some writing to the log volumes as well.) When I look at InfoCube 0TCT_C01 I only get a summary value for TIMEDM. In InfoCube 0TCT_C03 I get a little bit more details hinting to BW topics, but that is not what I was used e.g. with Oracle tracing or Active Workload Repository. So what could I do in HANA?
Introducing HANA Perftrace
When studying the available HANA documentation from SAP, it seems obvious that "perftrace" is the tool for performance analysis. You can find the performance trace feature In the "SAP HANA Database - SQL Reference Manual" on pages 122-124:
ALTER SYSTEM START PERFTRACE [<user_name>] [<application_user_name>] [PLAN_EXECUTION] [FUNCTION_PROFILER] [DURATION <duration_seconds>]
ALTER SYSTEM SAVE PERFTRACE [INTO FILE <file_name>]
SAP even tells you that these performance traces can be processed with HDBAdmin. So let's start! To keep things simple, I want to start with some kind of "Hello world!" example. Initially I just want to make sure I can perform the performance trace and analyze one of the simplest conceivable SQL statements. How about simply counting the number of users in the SAP system:
SELECT COUNT(*) AS ALL_USERS FROM USR02
Tracing vs. Documentation
Since I don't know perftrace yet I simply start it with all options (plan_execution and function_profiler). I would like to limit the tracing to my simple SQL statement, therefore I set the user_name and application_user_name. But wait! What is that?
hdbsql HDB=> alter system start perftrace saphdb hp plan_execution function_profiler duration 5
* 257: sql syntax error: incorrect syntax near "saphdb": line 1 col 30 (at pos 30) SQLSTATE: HY000
Did SAP forget to implement that feature? Or do I need single quotes/double quotes for the username? After some trial and error I give up and start tracing without user limitation:
hdbsql HDB=> alter system start perftrace plan_execution function_profiler duration 5
0 rows affected (17.696 msec)
Fine, tracing is activated and I have to hurry to start my SQL command. I use the DBA cockpit to execute my SELECT:
I click on button "Execute" et voila:
This is only a small demo box, so only 9 users were found in the table. The database interface measured the execution time as 3786 us. In the HANA trace directory some *.prf files have been written:
-rw-r--r-- 1 hdbadm sapsys 59036 Jul 19 11:06 indexserver.18357.000.prf
-rw-r--r-- 1 hdbadm sapsys 3481 Jul 19 11:06 nameserver.15660.000.prf
-rw-r--r-- 1 hdbadm sapsys 221 Jul 19 11:06 preprocessor.18018.000.prf
-rw-r--r-- 1 hdbadm sapsys 6283 Jul 19 11:06 statisticsserver.18450.000.prf
-rw-r--r-- 1 hdbadm sapsys 6809 Jul 19 11:06 xsengine.18575.000.prf
Finally SAP HANA has to consolidate that information into one perftrace file:
hdbsql HDB=> alter system save perftrace into file 'perftrace.tpt'
0 rows affected (3008.563 msec)
-rw-r--r-- 1 hdbadm sapsys 22039 Jul 19 11:13 perftrace.tpt
Analyzing traces via HDBAmin
The next step is to load that file into HDBadmin:
python hdbadmin.py --sqlUser=SYSTEM --sqlPassword=SYSTEMPASSWORD
With any HDBAdmin you can analyze the trace data of other HANA instances. Therefore initially you will get some summary view showing from which host the performance trace was taken and the timespan of the trace data:
Even though I tried to keep the traced timespan short, my SAP user triggered two SQL commands which are now found in the trace data. With some checking of the details I see that the first one is my SELECT on USR02. As expected, the indexserver executed my SELECT command and its duration was 1.2 ms:
On the next tab "Call Patterns" I find some information which seems to be only useful for SAP support:
Now on tab "Call Pattern" things get really interessting. This is what I have been looking for. The SELECT statement is broken down into processing steps, together with their processing time. And best of all, there is even a graphical view in a Gantt-Chart type visualizing the processing of my SQL command! Make sure you perform your perftraces with option FUNCTION_PROFILER, because otherwise this page will remain empty!
Please also note the "Export" button, there you can save part of the trace data to CSV-files, which can be easily imported into Excel.
Of course these HANA-internal processing steps are not officially documented, but at least you get some information via the button "Help". So this is the starting point to get a feeling for how HANA operates and to decide what is normal vs. what is not normal processing.
The other available tabs seem to be not so relevant. "SQL Plans" and "Column Store Plans" only provide summary information on the SQL plans. "Time Line" provides graphs of the overall CPU+memory consumption during the traced time period.
I really like this graphical overview on the "Call Pattern" tab. Similarly to SAP's root-cause-analysis and end-to-end tracing you can easily identify where most of the time is spent. Also the option of exporting the trace data to Excel is very useful, because you are not limited to HDBAdmin for trace data analysis. Maybe the SAP HANA wiki would be a good place to post some insights about SAP HANA methods? I just wonder why the perftrace command didn't fully work as documented by SAP, must be some stupid error by me.