Database corruption

Monday, 12 November 2012 · 14 messages · last reply 26 Nov 2012
AM
Antoni Mylka12 Nov 2012 15:30 #
Hi, We're developing an application that uses BaseX. In our tests, the application works properly for a couple of hours, makes queries to BaseX adds and removes data. Then suddenly some BaseX request will return the HTTP 500 response. From that point on all queries that make modifications in the database end in an error and the entire system grinds to a screeching halt. One of the experiments ran for four days, then we examined the access log to see that only the first 6 hours were OK, after that all BaseX queries would end in error. I'm going to investigate and will try to come up with as detailed a description of the issue as possible. For now the things I know are: 1. In our experiment, the application would make about 80000 successful queries over a period of 6 hours. Then it would get the first 500 error. 2. Afterwards it "seems" that the queries which don't modify anything end with 200, while all the modification queries end with a 500 error. That's to be confirmed. 3. BaseX 7.2.1 runs in a war deployed on Tomcat 7.0.32 on a linux system. 4. The access logs don't show anything interesting. 5. The catalina.out that shows the Tomcat standard output contains hundreds of exceptions of the following kind:
Exception in thread "Thread-78197" java.lang.RuntimeException: Data Access out of bounds [pre:1422612, indexSize:5540, access:5540 > 5539]
	at org.basex.util.Util.notexpected(Util.java:55)
	at org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:478)
	at org.basex.io.random.TableDiskAccess.read5(TableDiskAccess.java:211)
	at org.basex.data.Data.textOff(Data.java:432)
	at org.basex.data.DiskData.text(DiskData.java:228)
	at org.basex.index.value.DiskValues.get(DiskValues.java:295)
	at org.basex.index.value.UpdatableDiskValues.index(UpdatableDiskValues.java:133)
	at org.basex.data.DiskData$1.run(DiskData.java:461)
The thread name is different every time and the numbers in square brackets are also different. I don't see any patterns (yet). 6. BaseX is accessed from a single thread in a single application. AFAIK there are no concurrent requests, though that is to be confirmed. 7. The GC log shows that basex stays below 100M of used heap, which is well below the allotted Xmx setting of 2G. 8. We did three experiments and the same effect has been observed in all three, albeit after different periods of time: (59K queries and 4:25 hours, 37K queries and 2:56 hours, 76.8K queries and 6 hours). Things I intend to do: 1. Set up proper logging for BaseX, so that these errors don't end up in catalina.out, but in the proper log file. 2. Catch the first offending query, see if there is anything unusual about it. It certainly doesn't differ much from the successful queries. It simply updates the BaseX state to keep it in sync with an external data source. All the update queries are generated by the same template and there have been hundreds of successful ones before the first error occurs. 3. Manipulate the log settings, to see if it's possible to get something more meaningful out of them. 4. Try newer versions: 7.3 and the current trunk. I've seen emails similar about "Data Access out of bounds" but they don't seem relevant. As I said, I'll try to come up with more information, but if the error or the stack trace looks familiar - I'd be grateful for pointers. Thanks in advance,
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business
CG
Christian Grün12 Nov 2012 15:34 #
Dear Antoni, without having read all the elaborate details in your mail (thanks), I would strongly advise to try the latest stable 7.5 snapshot [1], which contains some important improvements reg. concurrent updates. I'm well aware that it feels inconvenient to use beta releases in productive environments, but the current version of 7.5 is very stable, and will be released soon without any major enhancements or legacy issues. Hope this helps, Christian [1] http://files.basex.org/releases/latest/
Quoted text · Antoni Mylka · 51 lines
On Mon, Nov 12, 2012 at 3:30 PM, Antoni Mylka <amy at basis06.ch> wrote: > Hi, > > We're developing an application that uses BaseX. In our tests, the application works properly for a couple of hours, makes queries to BaseX adds and removes data. Then suddenly some BaseX request will return the HTTP 500 response. From that point on all queries that make modifications in the database end in an error and the entire system grinds to a screeching halt. One of the experiments ran for four days, then we examined the access log to see that only the first 6 hours were OK, after that all BaseX queries would end in error. > > I'm going to investigate and will try to come up with as detailed a description of the issue as possible. For now the things I know are: > > 1. In our experiment, the application would make about 80000 successful queries over a period of 6 hours. Then it would get the first 500 error. > 2. Afterwards it "seems" that the queries which don't modify anything end with 200, while all the modification queries end with a 500 error. That's to be confirmed. > 3. BaseX 7.2.1 runs in a war deployed on Tomcat 7.0.32 on a linux system. > 4. The access logs don't show anything interesting. > 5. The catalina.out that shows the Tomcat standard output contains hundreds of exceptions of the following kind: > > Exception in thread "Thread-78197" java.lang.RuntimeException: Data Access out of bounds [pre:1422612, indexSize:5540, access:5540 > 5539] > at org.basex.util.Util.notexpected(Util.java:55) > at org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:478) > at org.basex.io.random.TableDiskAccess.read5(TableDiskAccess.java:211) > at org.basex.data.Data.textOff(Data.java:432) > at org.basex.data.DiskData.text(DiskData.java:228) > at org.basex.index.value.DiskValues.get(DiskValues.java:295) > at org.basex.index.value.UpdatableDiskValues.index(UpdatableDiskValues.java:133) > at org.basex.data.DiskData$1.run(DiskData.java:461) > > The thread name is different every time and the numbers in square brackets are also different. I don't see any patterns (yet). > 6. BaseX is accessed from a single thread in a single application. AFAIK there are no concurrent requests, though that is to be confirmed. > 7. The GC log shows that basex stays below 100M of used heap, which is well below the allotted Xmx setting of 2G. > 8. We did three experiments and the same effect has been observed in all three, albeit after different periods of time: (59K queries and 4:25 hours, 37K queries and 2:56 hours, 76.8K queries and 6 hours). > > Things I intend to do: > 1. Set up proper logging for BaseX, so that these errors don't end up in catalina.out, but in the proper log file. > 2. Catch the first offending query, see if there is anything unusual about it. It certainly doesn't differ much from the successful queries. It simply updates the BaseX state to keep it in sync with an external data source. All the update queries are generated by the same template and there have been hundreds of successful ones before the first error occurs. > 3. Manipulate the log settings, to see if it's possible to get something more meaningful out of them. > 4. Try newer versions: 7.3 and the current trunk. > > I've seen emails similar about "Data Access out of bounds" but they don't seem relevant. > > As I said, I'll try to come up with more information, but if the error or the stack trace looks familiar - I'd be grateful for pointers. > > Thanks in advance, > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk
AM
Antoni Mylka12 Nov 2012 19:17 #
Hi, Two further questions: 1. What's the cleanest way to get a log containing the actual query strings? AFAIU BaseX doesn't use any logging framework and the BaseXServlet.service has a finally block that prints the request headers (if Prop.debug is enabled) but not the request body. I thought about writing my own Filter for that purpose. 2. I've been trying to update BaseX to the latest snapshot, but the queries generated by my application, that used to work with 7.2.1 and 7.3 don't seem to work now. The body of a POST looks like this (\n means a newline character):
<?xml version="1.0" encoding="UTF-8"?>\n
<command xmlns="http://basex.org/rest"><text><![CDATA[\n
ADD TO 5d03ebad-dc6a-492c-9527-bd2ce3830080\n
<tx id="5d03ebad-dc6a-492c-9527-bd2ce3830080"\n
        dbId=""\n
        xmlns="http://our.namespace.com/xmlns/"\n
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"\n
        xmlns:xs="http://www.w3.org/2001/XMLSchema"\n
    <commit />\n
    <skip />\n
</tx>\n
\n
]]></text></command>
Now the question is what's wrong with this query. I get a 400 Bad Request response with the following error message. Stopped at line 1, column 43:\n Syntax: ADD (TO [path]) [input]\n Add resource to database.\n \n Adds [input] as [path] to the database.\n As I said this used to work with 7.3. I tried to diff the StringParser class between 7.3 and the current trunk. It seems to use the InputParser on a single line and not on the entire query. I can't spot anything that would explain this behaviour though. All kinds of comments welcome.
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business -- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail -----
Quoted text · Antoni Mylka · 79 lines
Von: "Antoni Mylka" <amy at basis06.ch> An: "Christian Grün" <christian.gruen at gmail.com> Gesendet: Montag, 12. November 2012 15:42:42 Betreff: Re: [basex-talk] Database corruption Dear Christian, Thanks for the tip. Will fix the logging settings and retest with the latest snapshot. Best regards, -- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail ----- Von: "Christian Grün" <christian.gruen at gmail.com> An: "Antoni Mylka" <amy at basis06.ch> CC: "basex-talk" <basex-talk at mailman.uni-konstanz.de> Gesendet: Montag, 12. November 2012 15:34:23 Betreff: Re: [basex-talk] Database corruption Dear Antoni, without having read all the elaborate details in your mail (thanks), I would strongly advise to try the latest stable 7.5 snapshot [1], which contains some important improvements reg. concurrent updates. I'm well aware that it feels inconvenient to use beta releases in productive environments, but the current version of 7.5 is very stable, and will be released soon without any major enhancements or legacy issues. Hope this helps, Christian [1] http://files.basex.org/releases/latest/ On Mon, Nov 12, 2012 at 3:30 PM, Antoni Mylka <amy at basis06.ch> wrote: > Hi, > > We're developing an application that uses BaseX. In our tests, the application works properly for a couple of hours, makes queries to BaseX adds and removes data. Then suddenly some BaseX request will return the HTTP 500 response. From that point on all queries that make modifications in the database end in an error and the entire system grinds to a screeching halt. One of the experiments ran for four days, then we examined the access log to see that only the first 6 hours were OK, after that all BaseX queries would end in error. > > I'm going to investigate and will try to come up with as detailed a description of the issue as possible. For now the things I know are: > > 1. In our experiment, the application would make about 80000 successful queries over a period of 6 hours. Then it would get the first 500 error. > 2. Afterwards it "seems" that the queries which don't modify anything end with 200, while all the modification queries end with a 500 error. That's to be confirmed. > 3. BaseX 7.2.1 runs in a war deployed on Tomcat 7.0.32 on a linux system. > 4. The access logs don't show anything interesting. > 5. The catalina.out that shows the Tomcat standard output contains hundreds of exceptions of the following kind: > > Exception in thread "Thread-78197" java.lang.RuntimeException: Data Access out of bounds [pre:1422612, indexSize:5540, access:5540 > 5539] > at org.basex.util.Util.notexpected(Util.java:55) > at org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:478) > at org.basex.io.random.TableDiskAccess.read5(TableDiskAccess.java:211) > at org.basex.data.Data.textOff(Data.java:432) > at org.basex.data.DiskData.text(DiskData.java:228) > at org.basex.index.value.DiskValues.get(DiskValues.java:295) > at org.basex.index.value.UpdatableDiskValues.index(UpdatableDiskValues.java:133) > at org.basex.data.DiskData$1.run(DiskData.java:461) > > The thread name is different every time and the numbers in square brackets are also different. I don't see any patterns (yet). > 6. BaseX is accessed from a single thread in a single application. AFAIK there are no concurrent requests, though that is to be confirmed. > 7. The GC log shows that basex stays below 100M of used heap, which is well below the allotted Xmx setting of 2G. > 8. We did three experiments and the same effect has been observed in all three, albeit after different periods of time: (59K queries and 4:25 hours, 37K queries and 2:56 hours, 76.8K queries and 6 hours). > > Things I intend to do: > 1. Set up proper logging for BaseX, so that these errors don't end up in catalina.out, but in the proper log file. > 2. Catch the first offending query, see if there is anything unusual about it. It certainly doesn't differ much from the successful queries. It simply updates the BaseX state to keep it in sync with an external data source. All the update queries are generated by the same template and there have been hundreds of successful ones before the first error occurs. > 3. Manipulate the log settings, to see if it's possible to get something more meaningful out of them. > 4. Try newer versions: 7.3 and the current trunk. > > I've seen emails similar about "Data Access out of bounds" but they don't seem relevant. > > As I said, I'll try to come up with more information, but if the error or the stack trace looks familiar - I'd be grateful for pointers. > > Thanks in advance, > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk
AM
Antoni Mylka13 Nov 2012 14:28 #
Hi, I debugged what goes on inside StringParser in the command posted earlier. It seems that the parser makes an assumption that the ADD command should fit on a single line. It works OK when I replace the newlines with spaces in the XML content to be added. It seems to me like a rather serious bug. Am I missing something obvious? I would really like to be able to push multi-line content to BaseX. If ADD TO is not the way to do that, then what is? The splitting of a command string into single lines has been done in https://github.com/BaseXdb/basex/commit/fffde7fa12a7cec6882f603638ea3e3ef366a4aa As far as I understand this change was about making the StringParser support .bxs scripts that can contain more than one command on each line. The distinction between a .bxs script and a "normal" command is done via the "single" flag. For normal commands "single" is set to true. Perhaps the easiest solution would be to keep the current processing if single is false, but if single is true, just use the whole string. I tried to create a patch that does it. Is the patch I attached worth anything? It seems to solve my immediate problem with the particular query I posted. I really don't understand much about BaseX codebase (or about git for that matter :) ) Please review.
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail -----
Quoted text · Antoni Mylka · 34 lines
Von: "Antoni Mylka" <amy at basis06.ch> An: "basex-talk" <basex-talk at mailman.uni-konstanz.de> Gesendet: Montag, 12. November 2012 19:17:35 Betreff: Re: [basex-talk] Database corruption Hi, Two further questions: 1. What's the cleanest way to get a log containing the actual query strings? AFAIU BaseX doesn't use any logging framework and the BaseXServlet.service has a finally block that prints the request headers (if Prop.debug is enabled) but not the request body. I thought about writing my own Filter for that purpose. 2. I've been trying to update BaseX to the latest snapshot, but the queries generated by my application, that used to work with 7.2.1 and 7.3 don't seem to work now. The body of a POST looks like this (\n means a newline character): <?xml version="1.0" encoding="UTF-8"?>\n <command xmlns="http://basex.org/rest"><text><![CDATA[\n ADD TO 5d03ebad-dc6a-492c-9527-bd2ce3830080\n <tx id="5d03ebad-dc6a-492c-9527-bd2ce3830080"\n dbId=""\n xmlns="http://our.namespace.com/xmlns/"\n xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"\n xmlns:xs="http://www.w3.org/2001/XMLSchema"\n <commit />\n <skip />\n </tx>\n \n ]]></text></command> Now the question is what's wrong with this query. I get a 400 Bad Request response with the following error message. Stopped at line 1, column 43:\n Syntax: ADD (TO [path]) [input]\n Add resource to database.\n \n Adds [input] as [path] to the database.\n As I said this used to work with 7.3. I tried to diff the StringParser class between 7.3 and the current trunk. It seems to use the InputParser on a single line and not on the entire query. I can't spot anything that would explain this behaviour though. All kinds of comments welcome. -- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business
CG
Christian Grün13 Nov 2012 15:12 #
Antoni, thanks in advance! Be sure I'll have a look at this later today.. Christian
Quoted text · Antoni Mylka · 97 lines
Am 13.11.2012 14:28 schrieb "Antoni Mylka" <amy at basis06.ch>: > Hi, > > I debugged what goes on inside StringParser in the command posted earlier. > It seems that the parser makes an assumption that the ADD command should > fit on a single line. It works OK when I replace the newlines with spaces > in the XML content to be added. It seems to me like a rather serious bug. > Am I missing something obvious? I would really like to be able to push > multi-line content to BaseX. If ADD TO is not the way to do that, then what > is? > > The splitting of a command string into single lines has been done in > > > https://github.com/BaseXdb/basex/commit/fffde7fa12a7cec6882f603638ea3e3ef366a4aa > > As far as I understand this change was about making the StringParser > support .bxs scripts that can contain more than one command on each line. > The distinction between a .bxs script and a "normal" command is done via > the "single" flag. For normal commands "single" is set to true. Perhaps the > easiest solution would be to keep the current processing if single is > false, but if single is true, just use the whole string. I tried to create > a patch that does it. Is the patch I attached worth anything? It seems to > solve my immediate problem with the particular query I posted. I really > don't understand much about BaseX codebase (or about git for that matter :) > ) Please review. > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > ----- Ursprüngliche Mail ----- > Von: "Antoni Mylka" <amy at basis06.ch> > An: "basex-talk" <basex-talk at mailman.uni-konstanz.de> > Gesendet: Montag, 12. November 2012 19:17:35 > Betreff: Re: [basex-talk] Database corruption > > Hi, > > Two further questions: > > 1. What's the cleanest way to get a log containing the actual query > strings? AFAIU BaseX doesn't use any logging framework and the > BaseXServlet.service has a finally block that prints the request headers > (if Prop.debug is enabled) but not the request body. I thought about > writing my own Filter for that purpose. > > 2. I've been trying to update BaseX to the latest snapshot, but the > queries generated by my application, that used to work with 7.2.1 and 7.3 > don't seem to work now. The body of a POST looks like this (\n means a > newline character): > > <?xml version="1.0" encoding="UTF-8"?>\n > <command xmlns="http://basex.org/rest"><text><![CDATA[\n > ADD TO 5d03ebad-dc6a-492c-9527-bd2ce3830080\n > <tx id="5d03ebad-dc6a-492c-9527-bd2ce3830080"\n > dbId=""\n > xmlns="http://our.namespace.com/xmlns/"\n > xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"\n > xmlns:xs="http://www.w3.org/2001/XMLSchema"\n > <commit />\n > <skip />\n > </tx>\n > \n > ]]></text></command> > > Now the question is what's wrong with this query. I get a 400 Bad Request > response with the following error message. > > Stopped at line 1, column 43:\n > Syntax: ADD (TO [path]) [input]\n > Add resource to database.\n > \n > Adds [input] as [path] to the database.\n > > As I said this used to work with 7.3. I tried to diff the StringParser > class between 7.3 and the current trunk. It seems to use the InputParser on > a single line and not on the entire query. I can't spot anything that would > explain this behaviour though. > > All kinds of comments welcome. > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk > >
CG
Christian Grünin reply to Antoni Mylka, 13 Nov 2012, 14:2814 Nov 2012 00:34 #
Hi Antoni, to start bottom up.. It feels as if you already know our code base quite well ;) Your description of the bug and the reasons for the changes in the code were absolutely right. I didn't manage to merge your patch out-of-box, but I adopted the general idea [1], which means the problem should now be resolved. By the way, we are planning to add support for our XML command syntax to the REST API [2]. Beside that, you could also use the PUT method in order to add documents to a database [3]; but I assume you already though about that anyway. Your feedback is welcome, thanks again, Christian [1] https://github.com/BaseXdb/basex/commit/d4abedd2080d98897533ed3c3329ac7030c5c3e3 [2] https://github.com/BaseXdb/basex/issues/559 [3] http://docs.basex.org/wiki/REST#PUT_Requests
Quoted text · Antoni Mylka · 67 lines
> I debugged what goes on inside StringParser in the command posted earlier. It seems that the parser makes an assumption that the ADD command should fit on a single line. It works OK when I replace the newlines with spaces in the XML content to be added. It seems to me like a rather serious bug. Am I missing something obvious? I would really like to be able to push multi-line content to BaseX. If ADD TO is not the way to do that, then what is? > > The splitting of a command string into single lines has been done in > > https://github.com/BaseXdb/basex/commit/fffde7fa12a7cec6882f603638ea3e3ef366a4aa > > As far as I understand this change was about making the StringParser support .bxs scripts that can contain more than one command on each line. The distinction between a .bxs script and a "normal" command is done via the "single" flag. For normal commands "single" is set to true. Perhaps the easiest solution would be to keep the current processing if single is false, but if single is true, just use the whole string. I tried to create a patch that does it. Is the patch I attached worth anything? It seems to solve my immediate problem with the particular query I posted. I really don't understand much about BaseX codebase (or about git for that matter :) ) Please review. > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > ----- Ursprüngliche Mail ----- > Von: "Antoni Mylka" <amy at basis06.ch> > An: "basex-talk" <basex-talk at mailman.uni-konstanz.de> > Gesendet: Montag, 12. November 2012 19:17:35 > Betreff: Re: [basex-talk] Database corruption > > Hi, > > Two further questions: > > 1. What's the cleanest way to get a log containing the actual query strings? AFAIU BaseX doesn't use any logging framework and the BaseXServlet.service has a finally block that prints the request headers (if Prop.debug is enabled) but not the request body. I thought about writing my own Filter for that purpose. > > 2. I've been trying to update BaseX to the latest snapshot, but the queries generated by my application, that used to work with 7.2.1 and 7.3 don't seem to work now. The body of a POST looks like this (\n means a newline character): > > <?xml version="1.0" encoding="UTF-8"?>\n > <command xmlns="http://basex.org/rest"><text><![CDATA[\n > ADD TO 5d03ebad-dc6a-492c-9527-bd2ce3830080\n > <tx id="5d03ebad-dc6a-492c-9527-bd2ce3830080"\n > dbId=""\n > xmlns="http://our.namespace.com/xmlns/"\n > xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"\n > xmlns:xs="http://www.w3.org/2001/XMLSchema"\n > <commit />\n > <skip />\n > </tx>\n > \n > ]]></text></command> > > Now the question is what's wrong with this query. I get a 400 Bad Request response with the following error message. > > Stopped at line 1, column 43:\n > Syntax: ADD (TO [path]) [input]\n > Add resource to database.\n > \n > Adds [input] as [path] to the database.\n > > As I said this used to work with 7.3. I tried to diff the StringParser class between 7.3 and the current trunk. It seems to use the InputParser on a single line and not on the entire query. I can't spot anything that would explain this behaviour though. > > All kinds of comments welcome. > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk >
AM
Antoni Mylka14 Nov 2012 13:15 #
Hi Christian, Thanks for the quick response. Just started another test with the latest snapshot. In the meantime I tried a patched version yesterday and stumbled upon another issue. One of our queries did something like this (snippet simplified for readability):
for $item in /somepath/someitemelement
    let $lmd as xs:dateTime := $item/value[@xsi:type="xs:dateTime"]
    let $dur := $now - $lmd
    where $dur > $itemMaxAge
    return $dur
}

<somepath>
  <someitemelement>
    <value xsi:type="xs:dateTime">2012-11-14T13:02:23Z</value>
  </someitemelement>
</somepath>
Now in 7.2.1 and in 7.3 the construct above would work i.e. * let $lmd as xs:dateTime was OK * the conversion from the <value> element to a dateTime value worked In the current snapshot I had to change that query. Things that worked are: * let $lmd := xs:dateTime($item/value[@xsi:type="xs:dateTime"]/text()) * let $lmd := $item/value[@xsi:type="xs:dateTime"] cast as xs:dateTime Now questions: 1. Was the query above wrong? 2. Which of the suggested new versions will be the fastest? The first "feels" like a double cast dateTime->string->dateTime. 3. What is the cleanest way to get a log with actual queries. I use tcpdump now, which is rather ugly. I tried the standard Tomcat's RequestDumperFilter, but it prints all the request information *apart* from the body. Do I have to write my own filter, as the guy on Stackoverlow did: http://stackoverflow.com/questions/1528628/logging-payload-of-posts-to-tomcat
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail -----
Quoted text · Christian Grün · 20 lines
Von: "Christian Grün" <christian.gruen at gmail.com> An: "Antoni Mylka" <amy at basis06.ch> CC: "basex-talk" <basex-talk at mailman.uni-konstanz.de> Gesendet: Mittwoch, 14. November 2012 00:34:47 Betreff: Re: [basex-talk] Database corruption Hi Antoni, to start bottom up.. It feels as if you already know our code base quite well ;) Your description of the bug and the reasons for the changes in the code were absolutely right. I didn't manage to merge your patch out-of-box, but I adopted the general idea [1], which means the problem should now be resolved. By the way, we are planning to add support for our XML command syntax to the REST API [2]. Beside that, you could also use the PUT method in order to add documents to a database [3]; but I assume you already though about that anyway. Your feedback is welcome, thanks again, Christian [1] https://github.com/BaseXdb/basex/commit/d4abedd2080d98897533ed3c3329ac7030c5c3e3 [2] https://github.com/BaseXdb/basex/issues/559 [3] http://docs.basex.org/wiki/REST#PUT_Requests
AM
Antoni Mylka14 Nov 2012 15:49 #
Hi, The test runs and I still get exceptions. They are different from those in 7.2.1 and don't happen every time, but are still scary. Improper use? Potential bug? Your feedback is welcome: Contact: basex-talk at mailman.uni-konstanz.de Version: BaseX 7.5 beta Java: Sun Microsystems Inc., 1.6.0_27 OS: Linux, amd64 Stack Trace: java.lang.ArrayIndexOutOfBoundsException: 2147483647 org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:486) org.basex.io.random.TableDiskAccess.read5(TableDiskAccess.java:211) org.basex.data.Data.textOff(Data.java:420) org.basex.data.DiskData.text(DiskData.java:234) org.basex.index.value.DiskValues.readKeyAt(DiskValues.java:285) org.basex.index.value.DiskValues.get(DiskValues.java:441) org.basex.index.value.UpdatableDiskValues.delete(UpdatableDiskValues.java:135) org.basex.data.DiskData.indexDelete(DiskData.java:427) org.basex.data.Data.delete(Data.java:608) org.basex.data.atomic.Replace.apply(Replace.java:35) org.basex.data.atomic.AtomicUpdateList.applyStructuralUpdates(AtomicUpdateList.java:310) org.basex.data.atomic.AtomicUpdateList.execute(AtomicUpdateList.java:298) org.basex.query.up.DatabaseUpdates.apply(DatabaseUpdates.java:175) org.basex.query.up.ContextModifier.apply(ContextModifier.java:88) org.basex.query.up.Updates.apply(Updates.java:122) org.basex.query.QueryContext.update(QueryContext.java:273) org.basex.query.QueryContext.value(QueryContext.java:258) org.basex.query.QueryContext.iter(QueryContext.java:243) org.basex.query.QueryProcessor.iter(QueryProcessor.java:76) org.basex.server.QueryListener.execute(QueryListener.java:127) org.basex.server.LocalQuery.execute(LocalQuery.java:53) org.basex.http.rest.RESTQuery.query(RESTQuery.java:93) org.basex.http.rest.RESTQuery.run(RESTQuery.java:47) org.basex.http.rest.RESTPost.run(RESTPost.java:107) org.basex.http.rest.RESTServlet.run(RESTServlet.java:14) org.basex.http.BaseXServlet.service(BaseXServlet.java:39)
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail -----
Quoted text · Antoni Mylka · 6 lines
Von: "Antoni Mylka" <amy at basis06.ch> An: "basex-talk" <basex-talk at mailman.uni-konstanz.de> Gesendet: Mittwoch, 14. November 2012 13:15:01 Betreff: Re: [basex-talk] Database corruption Hi Christian, Thanks for the quick response. Just started another test with the latest snapshot.
CG
Christian Grünin reply to Antoni Mylka, 14 Nov 2012, 13:1515 Nov 2012 01:03 #
Hi Antoni,
Quoted text · Antoni Mylka · 2 lines
> Now questions: > 1. Was the query above wrong?
yes, it was. We've further strengthened our type checks by introducing a distinction between casts and sequence type matchings, as demanded by the spec. In a nutshell: the type extension "as xs:dateTime" checks only if a value can be treated as item of type xs:dateTime, but it does not perform a cast.
Quoted text · Antoni Mylka · 4 lines
> * let $lmd := xs:dateTime($item/value[@xsi:type="xs:dateTime"]/text()) > * let $lmd := $item/value[@xsi:type="xs:dateTime"] cast as xs:dateTime > > 2. Which of the suggested new versions will be the fastest? The first "feels" like a double cast dateTime->string->dateTime.
Both variants should take pretty much the same time, as "cast as" will be evaluated the same way as xs:dateTime(). In the first variant, however, you can get rid of the text() step.
Quoted text · Antoni Mylka · 3 lines
> 3. What is the cleanest way to get a log with actual queries. I use tcpdump now, which is rather ugly. I tried the standard Tomcat's RequestDumperFilter, but it prints all the request information *apart* from the body. Do I have to write my own filter, as the guy on Stackoverlow did: > > http://stackoverflow.com/questions/1528628/logging-payload-of-posts-to-tomcat
This would surely be an option. You may as well have a look into the server logs, found at data/.logs. It’s particularly useful for ordinary client requests and RESTXQ calls, but it could be enriched with some additional information if that looks useful. Hope this helps, Christian
CG
Christian Grünin reply to Antoni Mylka, 14 Nov 2012, 15:4915 Nov 2012 01:05 #
Quoted text · Antoni Mylka · 1 line
> The test runs and I still get exceptions. They are different from those in 7.2.1 and don't happen every time, but are still scary.
I agree, this looks a little bit frightening.. I guess it won’t be easy, but it would be great if you manage to create a reproducible test case.
Quoted text · Antoni Mylka · 56 lines
> Improper use? Potential bug? Your feedback is welcome: > Contact: basex-talk at mailman.uni-konstanz.de > Version: BaseX 7.5 beta > Java: Sun Microsystems Inc., 1.6.0_27 > OS: Linux, amd64 > Stack Trace: > java.lang.ArrayIndexOutOfBoundsException: 2147483647 > org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:486) > org.basex.io.random.TableDiskAccess.read5(TableDiskAccess.java:211) > org.basex.data.Data.textOff(Data.java:420) > org.basex.data.DiskData.text(DiskData.java:234) > org.basex.index.value.DiskValues.readKeyAt(DiskValues.java:285) > org.basex.index.value.DiskValues.get(DiskValues.java:441) > org.basex.index.value.UpdatableDiskValues.delete(UpdatableDiskValues.java:135) > org.basex.data.DiskData.indexDelete(DiskData.java:427) > org.basex.data.Data.delete(Data.java:608) > org.basex.data.atomic.Replace.apply(Replace.java:35) > org.basex.data.atomic.AtomicUpdateList.applyStructuralUpdates(AtomicUpdateList.java:310) > org.basex.data.atomic.AtomicUpdateList.execute(AtomicUpdateList.java:298) > org.basex.query.up.DatabaseUpdates.apply(DatabaseUpdates.java:175) > org.basex.query.up.ContextModifier.apply(ContextModifier.java:88) > org.basex.query.up.Updates.apply(Updates.java:122) > org.basex.query.QueryContext.update(QueryContext.java:273) > org.basex.query.QueryContext.value(QueryContext.java:258) > org.basex.query.QueryContext.iter(QueryContext.java:243) > org.basex.query.QueryProcessor.iter(QueryProcessor.java:76) > org.basex.server.QueryListener.execute(QueryListener.java:127) > org.basex.server.LocalQuery.execute(LocalQuery.java:53) > org.basex.http.rest.RESTQuery.query(RESTQuery.java:93) > org.basex.http.rest.RESTQuery.run(RESTQuery.java:47) > org.basex.http.rest.RESTPost.run(RESTPost.java:107) > org.basex.http.rest.RESTServlet.run(RESTServlet.java:14) > org.basex.http.BaseXServlet.service(BaseXServlet.java:39) > > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > > ----- Ursprüngliche Mail ----- > Von: "Antoni Mylka" <amy at basis06.ch> > An: "basex-talk" <basex-talk at mailman.uni-konstanz.de> > Gesendet: Mittwoch, 14. November 2012 13:15:01 > Betreff: Re: [basex-talk] Database corruption > > Hi Christian, > > Thanks for the quick response. Just started another test with the latest snapshot. > > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk
AM
Antoni Mylka21 Nov 2012 12:41 #
Hi Christian, Let's return with this discussion to the mailing list as I think this might be interesting for everybody. Summary: I had stability problems. In my tests, once BaseX reached certain size It would start throwing exceptions with stacktraces reaching deep into the low-level classes that shuffle the bits and bytes on disk. I now started a test run of our system with PARALLEL=1 and UPDINDEX=false. The system has been running without any exceptions for 17 hours. Starting with an empty data there have been almost 200K queries and commands. This is a record. Now, what exactly are the consequences of UPDINDEX being false. Can I do queries? What kind of queries I can't do? What kind of queries will be slower? Will the database rebuild the index automatically? When? What is the command to trigger an index rebuild manually. Is the index rebuild kind of a "stop-the-world" operation, so that BaseX will become unresponsive or will it be done in parallel. What are the benefits of the indices, can I live without them?
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business ----- Ursprüngliche Mail -----
Quoted text · Christian Grün · 10 lines
Von: "Christian Grün" <christian.gruen at gmail.com> An: "Antoni Mylka" <amy at basis06.ch> Gesendet: Dienstag, 20. November 2012 16:46:30 Betreff: Re: [basex-talk] Database corruption Hi Antoni, > I'll also try to run an experiment without UPDINDEX. yes, this would be interesting. I did some more testing with the given queries, but couldn’t encounter something noteworthy so far.. Thanks, Christian
CG
Christian Grün21 Nov 2012 13:52 #
Hi Antoni, thanks for your feedback.
Quoted text · Antoni Mylka · 1 line
> I now started a test run of our system with PARALLEL=1 and UPDINDEX=false. The system has been running without any exceptions for 17 hours. Starting with an empty data there have been almost 200K queries and commands. This is a record.
that's good to hear. My assumption is that PARALLEL!=1 and UPDINDEX=false would point to a concurrency issue, while PARALLEL=1 and UPDINDEX=true would point to a bug in the updatable data structures.
Quoted text · Antoni Mylka · 2 lines
> Now, what exactly are the consequences of UPDINDEX being false. > Can I do queries?
Absolutely; all queries are still possible.
Quoted text · Antoni Mylka · 1 line
> What kind of queries will be slower?
All those queries that depend on the value indexes (e.g., text and attribrute value indexes). See [1] for some examples.
Quoted text · Antoni Mylka · 1 line
> Will the database rebuild the index automatically?
Nope; this will exactly happen if UPDINDEX is set to true. In many cases, however, it will be much faster to perform updates with UPDINDEX=false and rebuild indexes manually afterwards, using OPTIMIZE or db:optimize().
Quoted text · Antoni Mylka · 1 line
> What is the command to trigger an index rebuild manually.
OPTIMIZE will recreate your outdated index structures. You may as well use CREATE INDEX to explicitly create/rebuild a specified index.
Quoted text · Antoni Mylka · 2 lines
> Is the index rebuild kind of a "stop-the-world" operation, so that BaseX will become unresponsive or will it be done in parallel. > What are the benefits of the indices, can I live without them?
As you guessed, indexing is flagged as a write operations and will thus queue other operations. In many use cases, this works fine, because indexing is a rather fast operation in BaseX But, quite naturally, the notion of what “fast” is depends very much on your context, and the choice for implicit or manual indexing depends on your envisaged read/write patterns. Hope this helps, Christian PS: I would be interested to hear if you have already thought about benchmarking 200K update operations with UPDINDEX=false, AUTOFLUSH=false and a final OPTIMIZE call. [1] http://docs.basex.org/wiki/Index#Value_Indexes
AM
Antoni Mylka26 Nov 2012 13:20 #
Hi Christian, Just to let you know. Running another experiment and seeing other issues. This is with BaseX75-20121114.004957.war configured with PARALLEL=1 and UPDINDEX=false. Indeed, the stack trace doesn't mention the Updates or AtomicUpdateList classes, but still not optimal. The good result from last week may have been intermittent. In my log there are about 72K queries at the moment and catalina.out contains 34 exceptions. They correspond to 34 HTTP 500 responses in the access log. Improper use? Potential bug? Your feedback is welcome: Contact: basex-talk at mailman.uni-konstanz.de Version: BaseX 7.5 beta Java: Sun Microsystems Inc., 1.6.0_27 OS: Linux, amd64 Stack Trace: java.lang.RuntimeException: Data Access out of bounds: - pre value: 1716983 - #used blocks: 6757 - #total locks: 6771 - access: 6756 (6757 > 6756] org.basex.util.Util.notexpected(Util.java:53) org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:489) org.basex.io.random.TableDiskAccess.read1(TableDiskAccess.java:189) org.basex.data.Data.kind(Data.java:281) org.basex.query.value.node.DBNode.<init>(DBNode.java:49) org.basex.query.value.seq.DBNodeSeq.itemAt(DBNodeSeq.java:81) org.basex.query.value.seq.DBNodeSeq.itemAt(DBNodeSeq.java:1) org.basex.query.value.seq.Seq$1.next(Seq.java:94) org.basex.query.path.MixedPath.iter(MixedPath.java:83) org.basex.query.QueryContext.iter(QueryContext.java:289) org.basex.query.flwor.For$1.init(For.java:121) org.basex.query.flwor.For$1.next(For.java:85) org.basex.query.flwor.FLWR$1.next(FLWR.java:63) org.basex.query.expr.Constr.add(Constr.java:66) org.basex.query.expr.CElem.item(CElem.java:84) org.basex.query.expr.CElem.item(CElem.java:1) org.basex.query.expr.CFrag.item(CFrag.java:1) org.basex.query.expr.ParseExpr.iter(ParseExpr.java:46) org.basex.query.QueryContext.iter(QueryContext.java:289) org.basex.query.QueryContext.iter(QueryContext.java:243) org.basex.query.QueryProcessor.iter(QueryProcessor.java:76) org.basex.server.QueryListener.execute(QueryListener.java:127) org.basex.server.LocalQuery.execute(LocalQuery.java:53) org.basex.http.rest.RESTQuery.query(RESTQuery.java:93) org.basex.http.rest.RESTQuery.run(RESTQuery.java:47) org.basex.http.rest.RESTPost.run(RESTPost.java:107) org.basex.http.rest.RESTServlet.run(RESTServlet.java:14) org.basex.http.BaseXServlet.service(BaseXServlet.java:39) javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
-- Antoni Myłka Software Engineer basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 http://www.basis06.ch - source of smart business
CG
Christian Grün26 Nov 2012 13:29 #
Antoni, sorry for the ongoing bug research. We recently had another look at our basex-tests repository, which includes various stress tests [1], and our internal test cases, but it seems to be pretty difficult for us to get the reported problems reproduced. If we should manage to get closer to the core problem, we’ll be glad to dive more into this. Christian [1] https://github.com/BaseXdb/basex-tests
Quoted text · Antoni Mylka · 55 lines
> Hi Christian, > > Just to let you know. Running another experiment and seeing other issues. This is with BaseX75-20121114.004957.war configured with PARALLEL=1 and UPDINDEX=false. Indeed, the stack trace doesn't mention the Updates or AtomicUpdateList classes, but still not optimal. The good result from last week may have been intermittent. In my log there are about 72K queries at the moment and catalina.out contains 34 exceptions. They correspond to 34 HTTP 500 responses in the access log. > > Improper use? Potential bug? Your feedback is welcome: > Contact: basex-talk at mailman.uni-konstanz.de > Version: BaseX 7.5 beta > Java: Sun Microsystems Inc., 1.6.0_27 > OS: Linux, amd64 > Stack Trace: > java.lang.RuntimeException: Data Access out of bounds: > - pre value: 1716983 > - #used blocks: 6757 > - #total locks: 6771 > - access: 6756 (6757 > 6756] > org.basex.util.Util.notexpected(Util.java:53) > org.basex.io.random.TableDiskAccess.cursor(TableDiskAccess.java:489) > org.basex.io.random.TableDiskAccess.read1(TableDiskAccess.java:189) > org.basex.data.Data.kind(Data.java:281) > org.basex.query.value.node.DBNode.<init>(DBNode.java:49) > org.basex.query.value.seq.DBNodeSeq.itemAt(DBNodeSeq.java:81) > org.basex.query.value.seq.DBNodeSeq.itemAt(DBNodeSeq.java:1) > org.basex.query.value.seq.Seq$1.next(Seq.java:94) > org.basex.query.path.MixedPath.iter(MixedPath.java:83) > org.basex.query.QueryContext.iter(QueryContext.java:289) > org.basex.query.flwor.For$1.init(For.java:121) > org.basex.query.flwor.For$1.next(For.java:85) > org.basex.query.flwor.FLWR$1.next(FLWR.java:63) > org.basex.query.expr.Constr.add(Constr.java:66) > org.basex.query.expr.CElem.item(CElem.java:84) > org.basex.query.expr.CElem.item(CElem.java:1) > org.basex.query.expr.CFrag.item(CFrag.java:1) > org.basex.query.expr.ParseExpr.iter(ParseExpr.java:46) > org.basex.query.QueryContext.iter(QueryContext.java:289) > org.basex.query.QueryContext.iter(QueryContext.java:243) > org.basex.query.QueryProcessor.iter(QueryProcessor.java:76) > org.basex.server.QueryListener.execute(QueryListener.java:127) > org.basex.server.LocalQuery.execute(LocalQuery.java:53) > org.basex.http.rest.RESTQuery.query(RESTQuery.java:93) > org.basex.http.rest.RESTQuery.run(RESTQuery.java:47) > org.basex.http.rest.RESTPost.run(RESTPost.java:107) > org.basex.http.rest.RESTServlet.run(RESTServlet.java:14) > org.basex.http.BaseXServlet.service(BaseXServlet.java:39) > javax.servlet.http.HttpServlet.service(HttpServlet.java:722) > > -- > Antoni Myłka > Software Engineer > > basis06 AG, Birkenweg 61, CH-3013 Bern - Fon +41 31 311 32 22 > http://www.basis06.ch - source of smart business > _______________________________________________ > BaseX-Talk mailing list > BaseX-Talk at mailman.uni-konstanz.de > https://mailman.uni-konstanz.de/mailman/listinfo/basex-talk

⚡Generated with XQuery