openlink
ANYTIME timeouts triggers by short queries
This behaviour popped up starting yesterday in a system running 7.20.3233. Our application service runs a variety of user-defined queries against Virtuoso. Quite suddenly, approximately half their queries (across multiple graph URIs) stopped working. Virtuoso logs showed a ton of anytime timeouts, but a) the logs looked different than I'd seen before, and b) based on eyeball observation and examination of our app logs, the queries were all failing in under 2 seconds and our timeout (passed in the SPARQL call), is set to 30,000ms.
In the following snippet, we're seeing the result of a SINGLE call to the SPARQL endpoint with a query. (I included the log lines before and after as well). For this one query, we're getting the "Returning partial results after anytime timeout" message once, but the "Returning incomplete results,..." message three times identically. This pattern plays out throughout the logs, and I don't think I've ever seen it do that before.
18:19:30 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 26.46M rnd 2.278M seq 26.28M same seg 132.7K same pg 3.773K same par 0 disk 0 spec disk 0B / 0
18:39:48 ERRS_0 S1TAT RC... Returning partial results after anytime timeout
18:39:48 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 589.4K rnd 82.16K seq 479.8K same seg 6.023K same pg 11.01K same par 0 disk 0 spec disk 0B / 0
18:39:48 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 589.4K rnd 82.16K seq 479.8K same seg 6.023K same pg 11.01K same par 0 disk 0 spec disk 0B / 0
18:39:48 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 589.4K rnd 82.16K seq 479.8K same seg 6.023K same pg 11.01K same par 0 disk 0 spec disk 0B / 0
19:17:10 Checkpoint started
19:17:10 Checkpoint finished, log reused
Elsewhere in the logs (less often, but clustered with these events) we're seeing a message "Anytime in itc ctx" which I haven't seen before.
18:18:53 ERRS_0 S1TAT RC... Anytime in itc ctx
18:18:53 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 216K rnd 16.38K seq 204.1K same seg 3.153K same pg 2.124K same par 107 disk 519 spec disk 0B / 0
18:18:53 ERRS_0 S1TAT RC... Anytime in itc ctx
18:18:53 ERRS_0 S1TAT RC... Returning partial results after anytime timeout
18:18:53 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 23.18M rnd 2.222M seq 23.02M same seg 126.9K same pg 2.656K same par 10 disk 162 spec disk 0B / 0
18:18:53 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 23.18M rnd 2.222M seq 23.02M same seg 126.9K same pg 2.656K same par 10 disk 162 spec disk 0B / 0
18:18:54 ERRS_0 S1TAT RC... Returning incomplete results, query interrupted by result timeout. Activity: 1.606M rnd 192.1K seq 1.403M same seg 82.13K same pg 10.25K same par 10 disk 346 spec disk 0B / 0
18:18:55 ERRS_0 S1TAT RC... Returning partial results after anytime timeout
Again, this came on rather suddenly, and I was able to confirm that the Virtuoso configuration had not been changed (deployed on Kubernetes). Configuration is set by passing these env vars at container startup, and I confirmed visually they are correct in the virtuoso.ini file.
Environment:
DBA_PASSWORD: <set to the key 'password' in secret 'virtuoso-password-secret'> Optional: false
VIRT_PARAMETERS_NUMBEROFBUFFERS: 1360000
VIRT_PARAMETERS_MAXDIRTYBUFFERS: 1000000
VIRT_PARAMETERS_TransactionAfterImageLimit: 500000000
VIRT_DATABASE_DATABASEFILE: /data/virtuoso/virtuoso.db
VIRT_DATABASE_ERRORLOGFILE: /data/virtuoso/virtuoso.log
VIRT_DATABASE_LOCKFILE: /data/virtuoso/virtuoso.lck
VIRT_DATABASE_TRANSACTIONFILE: /data/virtuoso/virtuoso.trx
VIRT_DATABASE_XA_PERSISTENT_FILE: /data/virtuoso/virtuoso.pxa
VIRT_TEMPDATABASE_DATABASEFILE: /data/virtuoso/virtuoso-temp.db
VIRT_TEMPDATABASE_TRANSACTIONFILE: /data/virtuoso/virtuoso-temp.trx
VIRT_PARAMETERS_TRACEON: errors
VIRT_PARAMETERS_DEFAULTISOLATION: 1
VIRT_PARAMETERS_MAXQUERYMEM: 1G
VIRT_SPARQL_RESULTSETMAXROWS: 50000
VIRT_SPARQL_MAXQUERYEXECUTIONTIME: 86400
VIRT_SPARQL_MAXQUERYCOSTESTIMATIONTIME: -1
Any thoughts on what could be happening here? Are there other conditions that could cause Virtuoso to throw an anytime timeout error when it clearly isn't waiting long enough?
What is the version for the Virtuoso Open Source Docker Container image being used? The docker image was updated with the latest stable/7 branch updates, some of which included Anytime query updates/fixes, thus please ensure you are using this latest build ...
Hi Hugh. They were running 7.2.6.3233, which if I'm not mistaken was the latest until a week ago.
I had a look at the sparql_io.sql you linked, but I'm not sure I understand the codebase well enough to know where some of those parameters are coming from: hard_timeout, etc. Can you elaborate on the condition this recent change is meant to address? Is it issue #983? That ticket doesn't really wrap up, so wondering if there was any additional resolution.
The latest Virtuoso Open Source docker container version is Version 7.2.7.3234-pthreads as of May 18 2022 (031118cc2) as per the docker hub site, so you are not using the latest version with the latest anytime fixes ...