Lock request timeout with no entry in systemtable "Locks"

[hannes_degenhart]

Hi all,

we're running MaxDB 7.8.02.37 in an non SAP environment.

After some days of normal operation the error message "Lock request timeout (SQL-HY000) (LOCK TABLE yyy IN EXCLUSIVE MODE" occurs in our application.

During our analyse we thougth that in this case there should occur some data entries in the system table "locks", but there are no datasets in there.

Using the database studio we can see in the task manager the task which produce the table lock (with task status vWait).

Actual we have to restart the database to come back to a normal operation (for a while 😞 ).

Is there a way to clean up the table state to get rid of the locking messages without doing a restart of the database?

Does somewho have any ideas about this behaviour?

Thanks

   Hannes

[thorsten_zielke · Accepted solution]

Hi Hannes,

I would suggest starting the Database Anlyzer (activated by default in SAP systems) and during the  next incident have a look at the 'dban.prt' log file.

Here is an example of what you should be looking for:
Task 139 (appl.24055) is waiting for lock 'row_exclusive' on table EUDB, locked 'row_share' from task 148 (appl. 24056)
Task 148 (appl.24056) is waiting for lock 'row_exclusive' on table D347T, locked 'row_exclusive' from task 139

The above 'dban.prt' is a plain text file, so no problems on reading this. The advanced expert files are 'csv' style - you will probably not need them...

Thorsten

[hannes_degenhart · Accepted solution]

Hi Thorsten,

Thanks for your advise. The analyser doesn't give some lines you are mentioning.

I waited two 15 min. cycles and there was 1 lock request timeout in the first and 5 in the second.

Here is the output of the DBAN.prt. I blanked some lines, which should not be from any interest:

---- Start DBAN.prt -------

===== #0

at 2014-10-07 13:33:22

*  I

*  I  Version information:

*  I  --------------------

*  I  Database Analyzer configuration file dbanalyzer78.cfg, version 7.8.02 Build 037-121-248-697

*  I  Kernel version: Kernel

7.8.02   Build 037-121-248-697

*  I

*  I  System information:

*  I  -------------------

*  I  Number of CPUs: 4, processor type: x86_64

*  I  Physical memory 16087 MB, virtual memory 15257 MB, memory allocated from instance: 9159 MB

*  I  Operating system: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2

*  I

*  I  Instance configuration information:

*  I  -----------------------------------

* W1  No configuration check of instance REALDB has been performed so far!

*  I  Number of CPUs 'MaxCPUs' usable by instance: 4, max user tasks: 300

*  I  Size of data cache 992218 pages (7.57 GB), 98.57% in use, size of converter cache 7548 pages (0.06 GB)

*  I  Size of pin area 49664 pages, 0.00% in use.

* W1  Limit of configured 'SharedSQLCommandCacheSize'(262144KB ) reached!

*  I  Number of data volumes 7, usable size 18199986 pages (138.85 GB), used size 13952196 pages (106.45 GB), filling lev

*  I

*  I  Additional information:

*  I  -----------------------

*  I  Instance REALDB (srv-syntia-real-db) is up since 2014-08-15 12:47:41

*  I  Database Analyzer (pid 16400, connected to task T514) is up since 2014-10-07 13:33:21

*  I  Diagnostic function activated! 'UseExtendedTimeMeasurement' : YES

*  I  Diagnostic function activated! 'EnableCommandMonitor' : YES

* W1  Number of tables where update statistics is required: 177

* W1  Owner: OMSREAL, table: JOBSUPPLIERPOSITION

* W1  Owner: OMSREAL, table: KDBLIST

...

* W1  Owner: OMSREAL, table: TICKETSTATE

* W1  Owner: OMSREAL, table: JOBSUPPLIER

*  I  16 tables contain > 1.000.000 records but only 20.000 rows will be sampled for statistics

* W1  Table OMSREAL.JOBPARTYREMARK contains 4791011 rows (96132 pages), sample rows: 20000

...

* W1  Table OMSREAL.JOBPARTYTIMESTAMP contains 1838587 rows (23600 pages), sample rows: 20000

* W2  Log queue overflows: 916, configured log queue pages: 50 for each of 4 log queues

* W2  Deadlocks detected: 1

* W2  Lock request timeouts: 19919

*  I  SQL commands executed: 1622571083

===== #1

at 2014-10-07 13:48:24

*  I  SQL commands executed: 525490, avg. 584.32 per second

* W1  4 command cache cleanups! 0 commands reloaded, 0 execution plans and 24203 commands deleted

*  I  UKT10: commands: 378812493, dispatches: 3621610859, user task 276 is running, 2 tasks are waiting for CPU

*  I  UKT10: user task 285 is waiting for CPU in state 'Command wait'

*  I  UKT10: user task 271 is waiting for CPU in state 'Command wait'

* W1  Selects and fetches selectivity 2.91%: 333190 selects and fetches, 193646568 rows read, 5643531 rows qualified

* W3  35073 table scans, selectivity 0.08%: 166541187 rows read, 125514 rows qualified

* W1  Lock request timeouts: 1

* W1  DATA39: collision rate 44.75%, 110461 collisions, no waits, 246814 accesses on region 43

* W1  TAB1: collision rate 80.69%, 144312 collisions, no waits, 178849 accesses on region 110

*  I  Garbage collector tasks activated 720 times, currently active: 0

*  I  Number of runnable user tasks: 1

*  I  server tasks activity. Dispatches: 46530, physical reads: 26 (50 pages), physical writes: 24 (24 pages)

*  I  CPU utilization: instance REALDB: 34.44% (usr: 33.56%, sys: 0.89%), host: 40.89% (usr: 34.89%, sys: 4.89%, wio: 1.1

*  I  Number of pages marked for reclustering: 63, clustered read operations: 50938, clustered pages read: 545516

===== #2

at 2014-10-07 14:03:25

*  I  SQL commands executed: 415692, avg. 461.49 per second

* W1  3 command cache cleanups! 0 commands reloaded, 0 execution plans and 26586 commands deleted

* W1  Selects and fetches selectivity 4.33%: 292760 selects and fetches, 200890477 rows read, 8706554 rows qualified

* W3  33963 table scans, selectivity 0.11%: 174027706 rows read, 191329 rows qualified

* W2  71 index range accesses, selectivity 2.28%: 105240 rows read, 2397 rows qualified

* W1  Lock request timeouts: 5

*  I  Garbage collector tasks activated 770 times, currently active: 0

*  I  server tasks activity. Dispatches: 27878, physical reads: 26 (126 pages), physical writes: 12 (12 pages)

*  I  CPU utilization: instance REALDB: 37.51% (usr: 36.63%, sys: 0.89%), host: 42.84% (usr: 37.51%, sys: 4.33%, wio: 1%,

*  I  Number of pages marked for reclustering: 117, clustered read operations: 44402, clustered pages read: 457567

*  I  Cluster compression checked 3 segments, blocks read: 94, pages moved: 15

---  END DBAN.prt -----

Perhaps you have any ideas about this!

Thanks and

best regards

   Hannes

[thorsten_zielke · Accepted solution]

Hmm, ok...

Can you access SAP note 1243937 (FAQ: SAP MaxDB/liveCache SQL-, Object Locks)? If so, have a brief look at paragraph 12c and then continue with section 19 (and 20 for DBA Cockpit, if it is a SAP system).
I essence, you query the internal system tables 'lockstatistics' and then 'domain.locks' and 'domain.lock_holder, 'domain.lock_requestor' and 'domain.lock_waits'.

Not sure if the Database Analyzer file 'DBAN_RUNNING_COMMANDS' has been downported to your 7.8 version - if you have it, you might check this as well.

Thorsten

[hannes_degenhart · Accepted solution]

Hi Thorsten,

we are using MaxDB in an non SAP environment. Therefore I can not access SAP note 1243937 (FAQ: SAP MaxDB/liveCache SQL-, Object Locks)!

I have queried the all internal system tables. 'Lockstatistics' doesn't show any interesting issues and all 'domain.lock*' tables were empty.

Today we restarted the database due to a rollout, so I'll check the Database Analyzer file 'DBAN_RUNNING_COMMANDS' (it is available in our version) as soon as the next lock situations occur.

Thanks

Hannes