[Nepomuk] Re: Virtuoso eating up CPUs

[Will Stephenson]

On 15/12/10 11:44, Will Stephenson wrote:
> On 07/12/10 09:02, Will Stephenson wrote:
>> On Sunday 12 September 2010 22:18:27 Vishesh Handa wrote:
>>> Virtuoso goes crazy with some queries. :-/ We know about it, and can
>>> reproduce it. It's not a 4.5.1 issue, it's just a virtuoso thing.
>>>
>>> @Sebastian : Weren't your userVisibility patches supposed to fix this?
>>
>> Is there an upstream bug report for this that I can pursue? I'm still
>> seeing
>> this with 4.6 beta2.
>>
>> What techniques are there to check the state of the server to describe
>> these
>> 'virtuoso 100% cpu' cases? I'd like to have a bit more ability to support
>> virtuoso than just telling people to restart the server.
>
> So attached are several isql status() calls when virtuoso is going ape.
> The active query seems to be the same each time.

This one's even better - I thought my core i7 was getting a bit slow so 
I have a look and discover 12 queries that have been runaway for 3 hours 
each.

wstephenson at guano> isql -H localhost -S 1111 -U dba -P dba
Connected to OpenLink Virtuoso
Driver: 06.01.3127 OpenLink Virtuoso ODBC Driver
OpenLink Interactive SQL (Virtuoso), version 0.9849b.
Type HELP; for help and EXIT; to exit.
SQL> status();
REPORT
VARCHAR
_______________________________________________________________________________

OpenLink Virtuoso  Server
Version 06.01.3127-pthreads for Linux as of Dec 14 2010
Started on: 2010/12/15 11:14 GMT+60
Lite Mode

Database Status:
   File size 547356672, 66816 pages, 28875 free.
   47000 buffers, 23229 used, 0 dirty 3 wired down, repl age 0 0 w. io 
48 w/crsr.
   Disk Usage: 23324 reads avg 0 msec, 0% r 0% w last  0 s, 1014 writes,
     88 read ahead, batch = 184.  Autocompact 0 in 0 out, 0% saved.
Gate:  622 2nd in reads, 0 gate write waits, 0 in while read 0 busy scrap.
Log = 
/suse/wstephenson/.kde4/share/apps/nepomuk/repository/main/data/virtuosobackend/soprano-virtuoso.trx, 
87 bytes
37923 pages have been changed since last backup (in checkpoint state)
Current backup timestamp: 0x0000-0x00-0x00
Last backup date: unknown
Clients: 33 connects, max 25 concurrent
RPC: 3511 calls, 8 pending, 11 max until now, 0 queued, 2 burst reads 
(0%), 4 second brk=60088320
Checkpoint Remap 0 pages, 0 mapped back. 27 s atomic time.
     DB master 66816 total 28875 free 0 remap 0 mapped back
    temp  256 total 251 free

Lock Status: 0 deadlocks of which 0 2r1w, 0 waits,
    Currently 13 threads running 0 threads waiting 0 threads in vdb.
Pending:

Client 1111:1:-23:  Account: dba, 866 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-4:  Account: dba, 328615 bytes in, 563309 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-19:  Account: dba, 654 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-25:  Account: dba, 646 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-8:  Account: dba, 1254 bytes in, 468 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-2:  Account: dba, 20557 bytes in, 691318 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-27:  Account: dba, 2206 bytes in, 16655 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-15:  Account: dba, 1302 bytes in, 478 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:33:  Account: dba, 202 bytes in, 254 bytes out, 1 stmts.
PID: 29446, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-22:  Account: dba, 1006 bytes in, 1112 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-21:  Account: dba, 5464 bytes in, 19514 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-30:  Account: dba, 5478 bytes in, 18838 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-16:  Account: dba, 20836 bytes in, 4163 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-13:  Account: dba, 662 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-6:  Account: dba, 12981 bytes in, 4614 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-18:  Account: dba, 1012 bytes in, 1806 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-31:  Account: dba, 1002 bytes in, 535 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-17:  Account: dba, 870 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-10:  Account: dba, 662 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-26:  Account: dba, 4987 bytes in, 16805 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-29:  Account: dba, 648 bytes in, 331 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-9:  Account: dba, 1380 bytes in, 683 bytes out, 1 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 1 threads.
Locks:

Client 1111:1:-12:  Account: dba, 7158 bytes in, 22219 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-7:  Account: dba, 14411 bytes in, 5702 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:

Client 1111:1:-3:  Account: dba, 55107 bytes in, 131691 bytes out, 0 stmts.
PID: 4452, OS: unix, Application: unknown, IP#: 127.0.0.1
Transaction status: PENDING, 0 threads.
Locks:


Running Statements:
  Time (msec) Text
     10863605 sparql  select distinct ?r 
(bif:concat(bif:search_excerpt(bif:vector('thunder'),
      7966529 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
     10862450 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
      9283706 sparql  select count(distinct ?r) as ?cnt where { { { ?r 
?v1 ?v2 . ?v2 bif:conta
      9283706 sparql  select distinct ?r 
(bif:concat(bif:search_excerpt(bif:vector('display'),
     10853631 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
      9279929 sparql  select distinct ?r 
(bif:concat(bif:search_excerpt(bif:vector('login'), ?
           26 status()
     10804204 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
     10863610 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
      9277997 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
      9282068 sparql  select count(distinct ?r) as ?cnt where { { ?r ?v1 
?v2 . ?v2 bif:contain
      9279929 sparql  select count(distinct ?r) as ?cnt where { { { ?r 
?v1 ?v2 . ?v2 bif:conta


Hash indexes


170 Rows. -- 30 msec.