Help understanding Analyzer output

[Former Member]

Can anyone help on understanding the db analyzer output attached ?

The MaxCPUs message is clear I'd like to understand there are some issues that can be fixed.

Thank you !!

===== #0          at 2009-03-20 11:53:42
*  I  Database Analyzer configuration file dbanalyzer77.cfg, version 7.7.06 Build 009-123-202-944
*  I  Number of logical CPUs: 8, physical CPUs: 2, processor type: x86_64
*  I  Configuration: number of CPUs (MAXCPU): 6, max user tasks: 1020
*  I  'MaxCPUs' (6) exceeds number of physical CPUs (2)!
*  I  Physical memory 16088 MB, virtual memory 16386 MB, memory allocated from instance: 5292 MB
*  I  Operating system: Linux 2.6.23.1-42.fc8 #1 SMP Tue Oct 30 13:18:33 EDT 2007
*  I  Kernel version: Kernel    7.7.06   Build 009-123-202-944
*  I  Instance ECF3 (fatboy) is up since  23:59:58
*  I  Number of data volumes: 2
*  I  SQL commands executed: 174857156
* W1  Number of tables where update statistics is required: 1
* W1  Owner: DBA, table: SYSUPGRADEHISTORY
* W1  Lock list escalations: 12
*  I  Size of data cache 4094.43 MB, used data size in instance 1364.88 MB
* W3  Log automatic overwrite is set to 'on' !

===== #1          at 2009-03-20 11:54:42
*  I  SQL commands executed: 2148, avg. 39.31 per second
*  I  Active User tasks found in state 'Enter ExclLock': 2
*  I  Active User tasks found in state 'Running': 2
*  I  Active User tasks found in state 'Connect close': 1
*  I  Runnable User tasks found in state 'Enter ExclLock': 2
*  I  UKT11: commands: 25316973, dispatches: 109499812, user task 785 is running, 1 tasks are waiting for CPU
*  I  UKT10: commands: 18359305, dispatches: 107190388, user task 617 is running, 1 tasks are waiting for CPU
*  I  UKT10: user task 620 is waiting for CPU in state 'Enter ExclLock'
*  I  UKT11: user task 788 is waiting for CPU in state 'Enter ExclLock'
* W2  74 primary key range accesses, selectivity 0.33%: 31873 rows read, 106 rows qualified
*  I  CPU utilization: instance ECF3: 101.64% (usr: 101.64%, sys: 0%) host: 104.92% (usr: 103.28%, sys: 1.64%, idle: 691.8%)

===== #2          at 2009-03-20 11:55:43
*  I  SQL commands executed: 2527, avg. 46.28 per second
*  I  Active User tasks found in state 'Running': 1
*  I  Active User tasks found in state 'Connect close': 2
*  I  Active User tasks found in state 'ExclLock Yield': 1
*  I  Runnable User tasks found in state 'ExclLock Yield': 1
*  I  UKT11: commands: 25318126, dispatches: 109644955, user task 784 is running, 1 tasks are waiting for CPU
*  I  UKT11: user task 790 is waiting for CPU in state 'ExclLock Yield'
* W3  27 primary key range accesses, selectivity 0.17%: 16227 rows read, 27 rows qualified
*  I  DATA50: collision rate 3.29%, 436543 collisions, 1 waits (0%), 13256056 accesses on region 54
* W3  User task 1130 blocked in state 'Connect close' since 60s, application pid 1510
*  I  CPU utilization: instance ECF3: 113.33% (usr: 113.33%, sys: 0%) host: 115% (usr: 115%, sys: 0%, idle: 691.67%)

===== #3          at 2009-03-20 11:56:43
*  I  SQL commands executed: 1379, avg. 26.7 per second
* W3  20 primary key range accesses, selectivity 0.20%: 10148 rows read, 20 rows qualified
*  I  CPU utilization: instance ECF3: 47.54% (usr: 47.54%, sys: 0%) host: 50.82% (usr: 49.18%, sys: 1.64%, idle: 742.62%)

===== #4          at 2009-03-20 11:57:44
*  I  SQL commands executed: 6910, avg. 119.33 per second
*  I  Active User tasks found in state 'Connect close': 1
* W2  240 table scans, selectivity 0.64%: 196678 rows read, 1267 rows qualified
* W3  57 primary key range accesses, selectivity 0.28%: 26740 rows read, 76 rows qualified
* W2  330 index accesses, selectivity 1.54%: 36056 rows read, 557 rows qualified
*  I  CPU utilization: instance ECF3: 45% (usr: 45%, sys: 0%) host: 46.67% (usr: 46.67%, sys: 0%, idle: 760%)

===== #5          at 2009-03-20 11:58:44
*  I  SQL commands executed: 1522, avg. 29.05 per second
*  I  Active User tasks found in state 'Running': 1
* W3  56 primary key range accesses, selectivity 0.20%: 27880 rows read, 56 rows qualified
*  I  CPU utilization: instance ECF3: 73.77% (usr: 73.77%, sys: 0%) host: 78.69% (usr: 77.05%, sys: 1.64%, idle: 716.39%)

===== #6          at 2009-03-20 11:59:45
*  I  SQL commands executed: 1557, avg. 30.12 per second
*  I  Active User tasks found in state 'Running': 1
* W3  38 primary key range accesses, selectivity 0.16%: 23366 rows read, 38 rows qualified
*  I  CPU utilization: instance ECF3: 51.67% (usr: 51.67%, sys: 0%) host: 55% (usr: 53.33%, sys: 1.67%, idle: 755%)

===== #7          at 2009-03-20 12:00:45
*  I  SQL commands executed: 5712, avg. 97.74 per second
*  I  Active User tasks found in state 'Running': 1
* W3  47 primary key range accesses, selectivity 0.16%: 28046 rows read, 46 rows qualified
*  I  CPU utilization: instance ECF3: 73.77% (usr: 73.77%, sys: 0%) host: 75.41% (usr: 75.41%, sys: 0%, idle: 718.03%)

===== #8          at 2009-03-20 12:01:46
*  I  SQL commands executed: 1565, avg. 30.25 per second
* W3  42 primary key range accesses, selectivity 0.17%: 24666 rows read, 42 rows qualified
*  I  DATA50: collision rate 4.43%, 444353 collisions, no waits, 10038277 accesses on region 54
*  I  CPU utilization: instance ECF3: 86.67% (usr: 86.67%, sys: 0%) host: 91.67% (usr: 90%, sys: 1.67%, idle: 716.67%)

===== #9          at 2009-03-20 12:02:46
*  I  SQL commands executed: 2111, avg. 38.7 per second
*  I  Active User tasks found in state 'Running': 1
*  I  Active User tasks found in state 'Connect close': 1
* W3  53 primary key range accesses, selectivity 0.16%: 33101 rows read, 53 rows qualified
*  I  CPU utilization: instance ECF3: 86.89% (usr: 85.25%, sys: 1.64%) host: 86.89% (usr: 86.89%, sys: 0%, idle: 706.56%)

===== #10         at 2009-03-20 12:03:47
*  I  SQL commands executed: 1293, avg. 25.72 per second
* W3  43 primary key range accesses, selectivity 0.17%: 24667 rows read, 43 rows qualified
*  I  CPU utilization: instance ECF3: 65% (usr: 65%, sys: 0%) host: 70% (usr: 68.33%, sys: 1.67%, idle: 736.67%)

[Former Member · Accepted solution]

Dear Lars,

thank you for your answer.

Now MaxSQLLocks is set to 50.000. How can I found the correct number to have good performances ?

And is there a method to find exactly which SQL statements should be fixed to solve the other issues ?

SQL statements are generated by hibernate so they are out of my control but I think that knowing exactly where's the problem I can try to fix it.

Thank you !!

[lbreddemann · Accepted solution]

> Now MaxSQLLocks is set to 50.000. How can I found the correct number to have good performances ?

There is no correct answer.

The number of available locks is either enough or not.

Lock escalations should be avoided in any case. It's sounds simple, but here it really is.

Whenever your transaction knows that it's going to touch and lock a complete table, then it would be better to actively lock the table than to wait for an esacalation.

> And is there a method to find exactly which SQL statements should be fixed to solve the other issues ?

Sure - check the SDN Wiki.

There is a whole big chapter on performance analysis and tuning.

Fist steps would include to activate the command monitor and look out for statements with low selectivity.

Once you've found them, review the execution plan and check it against the available key/index structure.

> SQL statements are generated by hibernate so they are out of my control but I think that knowing exactly where's the problem I can try to fix it.

That's a common issue with generated statements.

Anyhow, quite often one can improve things by adding indexes to the tables in order to better support the queries.

So that would be an approach.

regards,

Lars

[Former Member]

Dear Lars,

the statement that seems to create the issue is only one:

SELECT ALBEROGENE0_.ID_ALBEROARTICOLI AS ID1_54_, ALBEROGENE0_.CODICE AS 
CODICE54_, ALBEROGENE0_.PATH AS PATH54_, ALBEROGENE0_.DESCRIZIONE AS DESCRIZI4_54_,
 ALBEROGENE0_.HAFIGLI AS HAFIGLI54_, ALBEROGENE0_.ORDINAMENTO AS ORDINAME6_54_
 FROM ECF3.ALBEROGENERATO ALBEROGENE0_ WHERE ALBEROGENE0_.ID_ALBEROARTICOLI=?
 AND (ALBEROGENE0_.PATH||ALBEROGENE0_.CODICE)=?

Here ID_ALBEROARTICOLI, PATH and CODICE all has an index.

Can the problem be that PATH and CODICE are joined ? Do you have an hint to solve the issue ?

Thank you !!

Edited by: Andrea Vettori on Mar 20, 2009 4:43 PM

Edited by: Andrea Vettori on Mar 20, 2009 4:44 PM

[lbreddemann]

>

> SELECT ALBEROGENE0_.ID_ALBEROARTICOLI AS ID1_54_, ALBEROGENE0_.CODICE AS 
> CODICE54_, ALBEROGENE0_.PATH AS PATH54_, ALBEROGENE0_.DESCRIZIONE AS DESCRIZI4_54_,
>  ALBEROGENE0_.HAFIGLI AS HAFIGLI54_, ALBEROGENE0_.ORDINAMENTO AS ORDINAME6_54_
>  FROM ECF3.ALBEROGENERATO ALBEROGENE0_ WHERE ALBEROGENE0_.ID_ALBEROARTICOLI=?
>  AND (ALBEROGENE0_.PATH||ALBEROGENE0_.CODICE)=?
> 
> 

>

> Here ID_ALBEROARTICOLI, PATH and CODICE all has an index.

>

> Can the problem be that PATH and CODICE are joined ? Do you have an hint to solve the issue ?

Don't know yet.

Please show us the explain for the statement.

And, well, using concatenation like this

AND (ALBEROGENE0_.PATH||ALBEROGENE0_.CODICE)=?

in the WHERE clause is allowed but it cannot be supported by an index.

Actually I don't even see the reason here, since obviously both values are known.

Therefore it would be better to have

AND ALBEROGENE0_.PATH    = ?
AND ALBEROGENE0_.CODICE =?

instead.

regards,

Lars

[Former Member]

Here's the explain output for one common parameters values case :

	ALBEROGENE0_		RANGE CONDITION FOR KEY	        12
		ID_ALBEROARTICOLI	     (USED KEY COLUMN)	
	JDBC_CURSOR_18		   RESULT IS NOT COPIED , COSTVALUE IS	         5
	JDBC_CURSOR_18		QUERYREWRITE - APPLIED RULES:	
	JDBC_CURSOR_18		   DistinctPullUp	         1

in the WHERE clause is allowed but it cannot be supported by an index.
Actually I don't even see the reason here, since obviously both values are known.

No I know only the concatenation of the two values at the query execution time.

Is it possible to create an index on the concatenation of the fields ?

Thank you !!

[lbreddemann]

> Here's the explain output for one common parameters values case :

>

>

> 	ALBEROGENE0_		RANGE CONDITION FOR KEY	        12
> 		ID_ALBEROARTICOLI	     (USED KEY COLUMN)	
> 	JDBC_CURSOR_18		   RESULT IS NOT COPIED , COSTVALUE IS	         5
> 	JDBC_CURSOR_18		QUERYREWRITE - APPLIED RULES:	
> 	JDBC_CURSOR_18		   DistinctPullUp	         1
> 

>

> No I know only the concatenation of the two values at the query execution time.>

> Is it possible to create an index on the concatenation of the fields ?

Unfortunately, this is not possible.

And actually as we see this seems to be exactly the issue here, since only ID_ALBEROARTICOLI can be used (but at least over the primary B*tree).

If you could make a function call instead this concatenation, than you could use the new MaxDB 7.7 feature I demonstrated in my last blog [2 things about 7.7|https://weblogs.sdn.sap.com/pub/wlg/13632 [original link is broken] [original link is broken] [original link is broken]].

Anyhow, since the table ALBERGOGEN0 is tiny the overall effect to the system response time would probably not be so big.

See, the DBAnalyzer warnings don't tell you, how long the inefficient accesses took.

It may be completely irrelevant to you, therefore I usually don't start checking the database performance by reading all warnings of DBAnalyzer.

Instead I look out for my important transactions that run too slow and try to figure out, where the time is spend.

regards,

Lars

[Former Member]

Instead I look out for my important transactions that run too slow and try to figure out, where the time is spend.

Are you saying to run the analyzer for longer time to see if other different issues are found ?

[lbreddemann]

> Are you saying to run the analyzer for longer time to see if other different issues are found ?

Well, DBanalyzer should run all the time, anyhow.

It can be a very handy tool to figure out, complex performance scenarios and to aggregate performance data from the past to have something to compare current values to.

But usually you would need to have the DB50 transaction of NetWeaver to comfortably use all these information (ok- it's not THAT comfortable.).

Anyway - DBAnalyzer takes a snapshot of performance relevant counters every 900 sec. (15 mins).

This data may help to identify general issues or high load times etc.

DBAnalyzer however cannot tell you, why transaction xyz is slow.

Since you don't want to waste your time to tune a statement like the above one to run in 0.3 ms instead of 0.45 ms (well, maybe this would be important to you - don't know), you would not chase every single warning, until everything is 'green'.

Instead you would pick the most important transaction where your users say. "this one is far too slow" and analyze it.

Doing it this way ensures that you don't waste time on things that have no or small impact to your users.

best regards and a nice weekend,

Lars

[Former Member]

Sure - check the SDN Wiki.
There is a whole big chapter on performance analysis and tuning.
Fist steps would include to activate the command monitor and look out for statements with low selectivity.
Once you've found them, review the execution plan and check it against the available key/index structure.

I'll try to follow these suggestions.

Thank you !!

[lbreddemann]

Hi again Andrea!

> Can anyone help on understanding the db analyzer output attached ?

> The MaxCPUs message is clear I'd like to understand there are some issues that can be fixed.

Ok, let's see if we can provide a free walkthrough..

> ===== #0 at 2009-03-20 11:53:42

> * I Database Analyzer configuration file dbanalyzer77.cfg, version 7.7.06 Build 009-123-202-944

> * I Number of logical CPUs: 8, physical CPUs: 2, processor type: x86_64

> * I Configuration: number of CPUs (MAXCPU): 6, max user tasks: 1020

> * I 'MaxCPUs' (6) exceeds number of physical CPUs (2)!

> * I Physical memory 16088 MB, virtual memory 16386 MB, memory allocated from instance: 5292 MB

> * I Operating system: Linux 2.6.23.1-42.fc8 #1 SMP Tue Oct 30 13:18:33 EDT 2007

> * I Kernel version: Kernel 7.7.06 Build 009-123-202-944

> * I Instance ECF3 (fatboy) is up since 23:59:58

> * I Number of data volumes: 2

> * I SQL commands executed: 174857156

Ok, the I (= Information) messages are nothing to worry about.

It's just for your information.

> * W1 Number of tables where update statistics is required: 1

> * W1 Owner: DBA, table: SYSUPGRADEHISTORY

> * W1 Lock list escalations: 12

Then there are warning messages (W1, W2, W3).

These indicates violations to check rules.

These check rules are defined by the dbanalyzer configuration file and the warning severity level is simply chosen by the developer of that file.

These two warnings above (spread over 3 lines) are:

1. One table needs new statitics - it's table DBA.SYSUPGRADEHISTORY.

DBAnalyzer knows this, because the MaxDB Kernel inserted the tablename into a special system table SYSUPDSTATWANTED when it accessed it and found the statistics did not fit to the data in the table.

Run a "update statistics as per system table" to clear this warning.

2. There had been lock list escalations in the database.

This happens when a single transactions holds more than 20% of all available lock entries. If this happens all row-locks are escalated to tablelocks.

Since this obviously isn't the greatest thing for parallel data access, this should be avoided.

Increate the MAXLOCKS parameter (say to 1000000 for starters) and check whether there are still lock escalations.

> * I Size of data cache 4094.43 MB, used data size in instance 1364.88 MB

> * W3 Log automatic overwrite is set to 'on' !

This one is serious!

With log automatic overwrite on you basically say "the data in this database is not important - I do not need to recover this database instance".

Think about whether this fits the situation!

> * W2 74 primary key range accesses, selectivity 0.33%: 31873 rows read, 106 rows qualified

This is a warning about badly tuned SQL statements.

For the 74 primary key ranges more than 310000 rows were read and only 106 fitted to the WHERE clause.

Check your statetements and think about providing appropriate indexes.

> * W3 27 primary key range accesses, selectivity 0.17%: 16227 rows read, 27 rows qualified

Same again - only worse.

> * W3 User task 1130 blocked in state 'Connect close' since 60s, application pid 1510

You may want to check what user task 1130 is up to.

Why is it hanging on "Connect close" ? Maybe a network issue!?

> * W3 20 primary key range accesses, selectivity 0.20%: 10148 rows read, 20 rows qualified

Ok, we already know this one.

You need to tune your SQL.

> * W2 240 table scans, selectivity 0.64%: 196678 rows read, 1267 rows qualified

And again - SQL not tuned good enough.

This time it's table scanes with a slightly better selectivity but still: reading nearly 200000 rows to get around 1200 is not the most clever thing to do.

> * W3 57 primary key range accesses, selectivity 0.28%: 26740 rows read, 76 rows qualified

dito.

> * W2 330 index accesses, selectivity 1.54%: 36056 rows read, 557 rows qualified

Same in green - only that this time a secondary index was used. But still the index is not selective enough.

> * W3 56 primary key range accesses, selectivity 0.20%: 27880 rows read, 56 rows qualified

Just like television - repetitions all over again.

> * W3 38 primary key range accesses, selectivity 0.16%: 23366 rows read, 38 rows qualified

They do this with Star Trek or Bonanza...:-)

ok, lets skip the rest.

I think you get the picture.

Hope that helps,

Lars