Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 23, 2012 at 4:27 PM, Nico Williams wrote: > On Mon, Jan 23, 2012 at 3:02 PM, John Elrick > wrote: > > I think I can inject something to do some measurements. I seem to > recall, > > however, that there was no substantive difference in the number of > > times sqlite3RunParser > > was called between the two. I'll check for: > > > > which query is being parsed > > how many times that particular query is parsed > > how many mallocs are stemming from that particular query. > > > > Maybe that will tell us something. > > I think it's fair to say that compiling a statement is expected to be > heavy-duty, but evaluating a compiled statement is expected to be > light-weight (not counting the work that the statement implies doing) > unless something triggers recompilation of the prepared statement. > > So the key, really, is to find out what's triggering the recompilation > of your statements. > > ...assuming that they ARE being recompiled. As I indicated, IIRC they are not. The issue may stem from the other thing I noticed, a substantial drop in the size of the average request to _malloc (by an order of magnitude). We shall see tomorrow; I'm done for the day. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 23, 2012 at 3:02 PM, John Elrick wrote: > I think I can inject something to do some measurements. I seem to recall, > however, that there was no substantive difference in the number of > times sqlite3RunParser > was called between the two. I'll check for: > > which query is being parsed > how many times that particular query is parsed > how many mallocs are stemming from that particular query. > > Maybe that will tell us something. I think it's fair to say that compiling a statement is expected to be heavy-duty, but evaluating a compiled statement is expected to be light-weight (not counting the work that the statement implies doing) unless something triggers recompilation of the prepared statement. So the key, really, is to find out what's triggering the recompilation of your statements. Nico -- ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 23, 2012 at 3:48 PM, Richard Hipp wrote: > On Mon, Jan 23, 2012 at 3:12 PM, John Elrick >wrote: > > > Brain hurts... > > > > Richard, more information for you. I rebuilt the call stack checking > > system into pure Delphi and confirmed that yy_reduce appears to be the > > malloc culprit. I further created a pair of procedures which I can use > to > > track the yyruleno from yy_reduce as though it were a call. Below is a > > representative sample of the data > > > > The parser does lots of little mallocs as it builds a parse tree. So I > expect it to generate a lot of malloc traffic. The question is why the > parser is being called so much. > > Can you put a printf() or something at > http://www.sqlite.org/src/artifact/1e86210d3976?ln=397 and figure out what > is being parsed so excessively? > > I think I can inject something to do some measurements. I seem to recall, however, that there was no substantive difference in the number of times sqlite3RunParser was called between the two. I'll check for: which query is being parsed how many times that particular query is parsed how many mallocs are stemming from that particular query. Maybe that will tell us something. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 23, 2012 at 3:12 PM, John Elrick wrote: > Brain hurts... > > Richard, more information for you. I rebuilt the call stack checking > system into pure Delphi and confirmed that yy_reduce appears to be the > malloc culprit. I further created a pair of procedures which I can use to > track the yyruleno from yy_reduce as though it were a call. Below is a > representative sample of the data > The parser does lots of little mallocs as it builds a parse tree. So I expect it to generate a lot of malloc traffic. The question is why the parser is being called so much. Can you put a printf() or something at http://www.sqlite.org/src/artifact/1e86210d3976?ln=397 and figure out what is being parsed so excessively? > > One interesting thing I noticed is that in 3.7.5, the average <1kb malloc > request size is 181.95 bytes. In 3.7.6 that average request size drops > to 17.74 bytes. > > Both examples are running the same dataset. > > versionmallocs mallocs by yy_reduce > 3.7.5 838,789 5,545 > 3.7.6 70,003,878 68,870,137 > > Major yy_reduce case consumers > > 3.7.5 > Count:947 = 'case_112 > yy_reduce' > Count:696 = 'case_189 > yy_reduce' > Count:537 = 'case_173 > yy_reduce' > Count:229 = 'case_243 > yy_reduce > case_173 > yy_reduce' > Count:214 = 'case_37 > yy_reduce > case_173 > yy_reduce' > > > 3.7.6 > Count: 5,606,345 = 'case_112 > yy_reduce' > Count: 5,267,458 = 'case_243 > yy_reduce > case_112 > yy_reduce' > Count: 4,922,428 = 'case_37 > yy_reduce > case_112 > yy_reduce' > Count: 4,623,402 = 'case_189 > yy_reduce > case_112 > yy_reduce' > Count: 4,278,372 = 'case_8 > yy_reduce > case_112 > yy_reduce' > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Brain hurts... Richard, more information for you. I rebuilt the call stack checking system into pure Delphi and confirmed that yy_reduce appears to be the malloc culprit. I further created a pair of procedures which I can use to track the yyruleno from yy_reduce as though it were a call. Below is a representative sample of the data. One interesting thing I noticed is that in 3.7.5, the average <1kb malloc request size is 181.95 bytes. In 3.7.6 that average request size drops to 17.74 bytes. Both examples are running the same dataset. versionmallocs mallocs by yy_reduce 3.7.5 838,789 5,545 3.7.6 70,003,878 68,870,137 Major yy_reduce case consumers 3.7.5 Count:947 = 'case_112 yy_reduce' Count:696 = 'case_189 yy_reduce' Count:537 = 'case_173 yy_reduce' Count:229 = 'case_243 yy_reduce case_173 yy_reduce' Count:214 = 'case_37 yy_reduce case_173 yy_reduce' 3.7.6 Count: 5,606,345 = 'case_112 yy_reduce' Count: 5,267,458 = 'case_243 yy_reduce case_112 yy_reduce' Count: 4,922,428 = 'case_37 yy_reduce case_112 yy_reduce' Count: 4,623,402 = 'case_189 yy_reduce case_112 yy_reduce' Count: 4,278,372 = 'case_8 yy_reduce case_112 yy_reduce' ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I may not have been clear that these two separate tests both used the Delphi bridge (as you refer to it). What they point to is an unusual interaction between our full application and SQLite is triggering the increase in malloc calls. On Sat, Jan 21, 2012 at 6:48 PM, Simon Slavin wrote: > > On 21 Jan 2012, at 11:20pm, Alek Paunov wrote: > > > 3.6.17: 14 seconds > > 3.7.9: 10 seconds > > > > This clearly demonstrates that the newer version of Sqlite is, all things > > being equal, superior in performance to the older. However, tests inside > > our Delphi application demonstrate that reaching the exact same point of > > the database result in the following times: > > > > Live Application > > > > 3.6.17: 16 seconds > > 3.7.9: 58 seconds > > Which implies that the fault is in the Delphi bridge to SQLite and any > pure examination of SQLite's behaviour isn't going to spot anything, right > ? So a better place to query this would be a Delphi list ? > > Simon. > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 21 Jan 2012, at 11:20pm, Alek Paunov wrote: > 3.6.17: 14 seconds > 3.7.9: 10 seconds > > This clearly demonstrates that the newer version of Sqlite is, all things > being equal, superior in performance to the older. However, tests inside > our Delphi application demonstrate that reaching the exact same point of > the database result in the following times: > > Live Application > > 3.6.17: 16 seconds > 3.7.9: 58 seconds Which implies that the fault is in the Delphi bridge to SQLite and any pure examination of SQLite's behaviour isn't going to spot anything, right ? So a better place to query this would be a Delphi list ? Simon. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 21.01.2012 16:00, John Elrick wrote: manifestation. As frustrating as it has been to narrow down the cause, I Frustrating ... ? John Elrick, 2012-01-13: """ I created a logging system which took a specific set of data and converted all of the automatically run queries to an SQL script which I could use in a test application. When testing this particular script using a test program which uses our Delphi wrappers the following times are observed: Test Application Run Batch Script 3.6.17: 14 seconds 3.7.9: 10 seconds This clearly demonstrates that the newer version of Sqlite is, all things being equal, superior in performance to the older. However, tests inside our Delphi application demonstrate that reaching the exact same point of the database result in the following times: Live Application 3.6.17: 16 seconds 3.7.9: 58 seconds """ ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I'll send it in a bit. I actually created the complete script a week ago. Richard, I greatly appreciate your time and the attention you've given this matter. I have no doubt this is a very esoteric issue which we just happened to hit the exact combination of events to force its manifestation. As frustrating as it has been to narrow down the cause, I have nothing but respect and gratitude for everyone who has attempted to help. Thank you all. On Jan 20, 2012 3:47 PM, "Richard Hipp" wrote: > On Fri, Jan 20, 2012 at 3:40 PM, John Elrick >wrote: > > > I don't mean to blow anyone off, but there are over 100 prepared queries > > involved in a very interlaced manner. Getting the EXPLAIN data is very > > time consuming and since we've gone way past that point already by > > obtaining call stack information, I am not interested in revisiting the > > territory unless there is a very good reason for it. At least I know we > > can successfully upgrade to 3.7.5 without any performance issues. It > would > > be nice to understand what is going on from that version forward, > however, > > because it is important that we be able to continue upgrades in the > future. > > > > We'd like to understand what SQLite is doing differently to cause your > problem, too. As you have already observed, most applications don't have > this issue. I'm not sure what your application is doing to make SQLite go > crazy will mallocs, but we'd like to know so that we can avoid such > situations in the future. > > Can you try this: Can you use the sqlite3_trace() interface to create a > log of all SQL statements that are evaluated. Then send me (perhaps > privately) the starting database and your log, so that I can run SQLite > through exactly the same set of operations you are running it through? > > > > > > > > > > On Fri, Jan 20, 2012 at 2:55 PM, John Elrick > >wrote: > > > > > The problem is not in the queries. The problem is in a two order of > > > magnitude increase in _mallocs between the versions. The _mallocs are > > > coming from sqlite3Parser. > > > > > > > > > On Fri, Jan 20, 2012 at 2:37 PM, Max Vlasov > > wrote: > > > > > >> On Fri, Jan 20, 2012 at 10:05 PM, John Elrick < > john.elr...@fenestra.com > > >> >wrote: > > >> > > >> > The change which results in a slow down occurred between 3.7.5.0 and > > >> > 3.7.6.0. > > >> > > > >> > > > >> What about EXPLAIN difference? Or just outputs of this prefix from > both > > >> versions? > > >> > > >> Max > > >> ___ > > >> sqlite-users mailing list > > >> sqlite-users@sqlite.org > > >> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > >> > > > > > > > > > > > > -- > > > John Elrick > > > Fenestra Technologies > > > 540-868-1377 > > > > > > > > > > > > -- > > John Elrick > > Fenestra Technologies > > 540-868-1377 > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 20, 2012 at 3:40 PM, John Elrick wrote: > I don't mean to blow anyone off, but there are over 100 prepared queries > involved in a very interlaced manner. Getting the EXPLAIN data is very > time consuming and since we've gone way past that point already by > obtaining call stack information, I am not interested in revisiting the > territory unless there is a very good reason for it. At least I know we > can successfully upgrade to 3.7.5 without any performance issues. It would > be nice to understand what is going on from that version forward, however, > because it is important that we be able to continue upgrades in the future. > We'd like to understand what SQLite is doing differently to cause your problem, too. As you have already observed, most applications don't have this issue. I'm not sure what your application is doing to make SQLite go crazy will mallocs, but we'd like to know so that we can avoid such situations in the future. Can you try this: Can you use the sqlite3_trace() interface to create a log of all SQL statements that are evaluated. Then send me (perhaps privately) the starting database and your log, so that I can run SQLite through exactly the same set of operations you are running it through? > > > On Fri, Jan 20, 2012 at 2:55 PM, John Elrick >wrote: > > > The problem is not in the queries. The problem is in a two order of > > magnitude increase in _mallocs between the versions. The _mallocs are > > coming from sqlite3Parser. > > > > > > On Fri, Jan 20, 2012 at 2:37 PM, Max Vlasov > wrote: > > > >> On Fri, Jan 20, 2012 at 10:05 PM, John Elrick >> >wrote: > >> > >> > The change which results in a slow down occurred between 3.7.5.0 and > >> > 3.7.6.0. > >> > > >> > > >> What about EXPLAIN difference? Or just outputs of this prefix from both > >> versions? > >> > >> Max > >> ___ > >> sqlite-users mailing list > >> sqlite-users@sqlite.org > >> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > >> > > > > > > > > -- > > John Elrick > > Fenestra Technologies > > 540-868-1377 > > > > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I don't mean to blow anyone off, but there are over 100 prepared queries involved in a very interlaced manner. Getting the EXPLAIN data is very time consuming and since we've gone way past that point already by obtaining call stack information, I am not interested in revisiting the territory unless there is a very good reason for it. At least I know we can successfully upgrade to 3.7.5 without any performance issues. It would be nice to understand what is going on from that version forward, however, because it is important that we be able to continue upgrades in the future. On Fri, Jan 20, 2012 at 2:55 PM, John Elrick wrote: > The problem is not in the queries. The problem is in a two order of > magnitude increase in _mallocs between the versions. The _mallocs are > coming from sqlite3Parser. > > > On Fri, Jan 20, 2012 at 2:37 PM, Max Vlasov wrote: > >> On Fri, Jan 20, 2012 at 10:05 PM, John Elrick > >wrote: >> >> > The change which results in a slow down occurred between 3.7.5.0 and >> > 3.7.6.0. >> > >> > >> What about EXPLAIN difference? Or just outputs of this prefix from both >> versions? >> >> Max >> ___ >> sqlite-users mailing list >> sqlite-users@sqlite.org >> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >> > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
The problem is not in the queries. The problem is in a two order of magnitude increase in _mallocs between the versions. The _mallocs are coming from sqlite3Parser. On Fri, Jan 20, 2012 at 2:37 PM, Max Vlasov wrote: > On Fri, Jan 20, 2012 at 10:05 PM, John Elrick >wrote: > > > The change which results in a slow down occurred between 3.7.5.0 and > > 3.7.6.0. > > > > > What about EXPLAIN difference? Or just outputs of this prefix from both > versions? > > Max > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 20, 2012 at 10:05 PM, John Elrick wrote: > The change which results in a slow down occurred between 3.7.5.0 and > 3.7.6.0. > > What about EXPLAIN difference? Or just outputs of this prefix from both versions? Max ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
The change which results in a slow down occurred between 3.7.5.0 and 3.7.6.0. On Fri, Jan 20, 2012 at 8:34 AM, John Elrick wrote: > Thank you sir. I'll start looking. > > > On Fri, Jan 20, 2012 at 8:27 AM, Richard Hipp wrote: > >> On Fri, Jan 20, 2012 at 8:14 AM, John Elrick > >wrote: >> >> > I asked in an earlier posting if the amalgamations were available >> > somewhere. >> > >> >> >> >> http://www.sqlite.org/sqlite-amalgamation-.zip where is one of: >> >> 3071000 >> 3070900 >> 3070800 >> 3070700 >> 3070603 >> 3070602 >> 3070601 >> 3070600 >> 3070500 >> 3070400 >> 3_7_3 >> 3_7_2 >> 3_7_1 >> 3_7_0 >> 3_6_23_1 >> 3_6_23 >> 3_6_22 >> 3_6_21 >> 3_6_20 >> 3_6_19 >> 3_6_18 >> 3_6_17 >> 3_6_16 >> >> -- >> D. Richard Hipp >> d...@sqlite.org >> ___ >> sqlite-users mailing list >> sqlite-users@sqlite.org >> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >> > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Thank you sir. I'll start looking. On Fri, Jan 20, 2012 at 8:27 AM, Richard Hipp wrote: > On Fri, Jan 20, 2012 at 8:14 AM, John Elrick >wrote: > > > I asked in an earlier posting if the amalgamations were available > > somewhere. > > > > > > http://www.sqlite.org/sqlite-amalgamation-.zip where is one of: > > 3071000 > 3070900 > 3070800 > 3070700 > 3070603 > 3070602 > 3070601 > 3070600 > 3070500 > 3070400 > 3_7_3 > 3_7_2 > 3_7_1 > 3_7_0 > 3_6_23_1 > 3_6_23 > 3_6_22 > 3_6_21 > 3_6_20 > 3_6_19 > 3_6_18 > 3_6_17 > 3_6_16 > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 20, 2012 at 8:14 AM, John Elrick wrote: > I asked in an earlier posting if the amalgamations were available > somewhere. > http://www.sqlite.org/sqlite-amalgamation-.zip where is one of: 3071000 3070900 3070800 3070700 3070603 3070602 3070601 3070600 3070500 3070400 3_7_3 3_7_2 3_7_1 3_7_0 3_6_23_1 3_6_23 3_6_22 3_6_21 3_6_20 3_6_19 3_6_18 3_6_17 3_6_16 -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I asked in an earlier posting if the amalgamations were available somewhere. Since C isn't my primary language and I'm building on Windows, I'd prefer to have the simplest possible route to recreating. But yes, that is precisely what I wanted to do in the beginning to identify the point where everything changed. On Thu, Jan 19, 2012 at 11:37 PM, Max Vlasov wrote: > John, another suggestion > > Can you test previous sqlite versions one by one towards older ones with > one of your problem queries until the results are "good" again and send > both good and bad EXPLAIN QUERY output here. I'm sure this will be greek > for most of us :), but when Richard or Dan look at the difference in the > vdbe code, they could notice something > > Max > > On Fri, Jan 20, 2012 at 1:17 AM, John Elrick >wrote: > > > One more useful comparison. The following query is prepared and step is > > called with these results: > > > > > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
John, another suggestion Can you test previous sqlite versions one by one towards older ones with one of your problem queries until the results are "good" again and send both good and bad EXPLAIN QUERY output here. I'm sure this will be greek for most of us :), but when Richard or Dan look at the difference in the vdbe code, they could notice something Max On Fri, Jan 20, 2012 at 1:17 AM, John Elrick wrote: > One more useful comparison. The following query is prepared and step is > called with these results: > > ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
One more useful comparison. The following query is prepared and step is called with these results: step: UPDATE RESPONSES SET RESPONSE_NAME = :RESPONSE_NAME WHERE RESPONSE_OID = :RESPONSE_OID Cumulative Allocated Memory: 10,992 Count of _malloc Calls:18 Cumulative Reallocated Memory: 0 Cumulative Reallocated Memory where nil: 0 Count of _realloc Calls: 0 Count of _realloc Calls where nil: 0 Count of _free Calls: 18 Cumulative _mallocs by size <= 1kb:1,704 bytes (9 count) 1kb to 4kb:9,288 bytes (9 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs by size <= 1kb:0 bytes (0 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs of nil pointers by size <= 1kb:0 bytes (0 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) step is called on the exact same prepared query 0.201 seconds later: Cumulative Allocated Memory: 439,424 Count of _malloc Calls:2,248 Cumulative Reallocated Memory: 5,080 Cumulative Reallocated Memory where nil: 0 Count of _realloc Calls: 23 Count of _realloc Calls where nil: 0 Count of _free Calls: 2,246 Cumulative _mallocs by size <= 1kb:175,160 bytes (2,047 count) 1kb to 4kb:264,264 bytes (201 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs by size <= 1kb:5,080 bytes (23 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs of nil pointers by size <= 1kb:0 bytes (0 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count)
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 11:49 AM, John Elrick wrote: > I've added more tracking to our libraries. Most queries result in minimal > (<200 calls) _malloc activity, But I have found several anomalies. I am > listing some representatives below. In the examples below, "step" is the > operation. Note also that all queries should have been prepared with > sqlite3_prepare_v2 before step is invoked. > A few points I forgot to mention: 1. Each of these snapshots are deltas in the values before the operation and after. So, using Example 3, the delta in cumulative malloc'd memory was 459,576 bytes and there were 2,323 calls to _malloc for this call to sqlite3_step. 2. Each of these is ONE operation, not a cumulative for all executions of that query 3. Example 3 represents an insert operation. I should add example values which would be inserted: :QUESTIONNAIRE_OID: Integer :QUESTIONNAIRE_NAME: string 9 characters long :definition_parent: Integer :instance_parent: Integer ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I've added more tracking to our libraries. Most queries result in minimal (<200 calls) _malloc activity, But I have found several anomalies. I am listing some representatives below. In the examples below, "step" is the operation. Note also that all queries should have been prepared with sqlite3_prepare_v2 before step is invoked. step: select distinct FORM_DEFINITIONS.FORM_DEFINITION_OID from FORM_DEFINITIONS, SURVEYS where SURVEYS.SURVEY_OID=:SURVEYS_SURVEY_OID and FORM_DEFINITIONS.FORM_DEFINITION_OID=:FORM_DEFINITIONS_FORM_DEFINITION_OID and FORM_DEFINITIONS.definition_parent=SURVEYS.SURVEY_OID order by FORM_DEFINITIONS.rowid Cumulative Allocated Memory: 430,208 Count of _malloc Calls:2,255 Cumulative Reallocated Memory: 5,632 Cumulative Reallocated Memory where nil: 0 Count of _realloc Calls: 22 Count of _realloc Calls where nil: 0 Count of _free Calls: 2,258 Cumulative _mallocs by size <= 1kb:175,232 bytes (2,063 count) 1kb to 4kb:254,976 bytes (192 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs by size <= 1kb:5,632 bytes (22 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs of nil pointers by size <= 1kb:0 bytes (0 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Here is another anomaly: step: insert into background_constraints values ( :sequence_instance_oid , :sequence_definition_oid ) Cumulative Allocated Memory: 426,240 Count of _malloc Calls:2,221 Cumulative Reallocated Memory: 4,520 Cumulative Reallocated Memory where nil: 0 Count of _realloc Calls: 15 Count of _realloc Calls where nil: 0 Count of _free Calls: 2,233 Cumulative _mallocs by size <= 1kb:171,264 bytes (2,029 count) 1kb to 4kb:254,976 bytes (192 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs by size <= 1kb:4,520 bytes (15 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 8:25 AM, John Elrick wrote: > > > On Thu, Jan 19, 2012 at 8:15 AM, Richard Hipp wrote: > >> On Thu, Jan 19, 2012 at 8:10 AM, John Elrick > >wrote: >> >> > >> > I've been reading through the code. Do I understand correctly that if >> one >> > prepared statement binding is changed in such a way as may influence the >> > choice of the query plan that all the prepared statements for that >> database >> > connection are flagged for being re-prepared? >> > >> > >> No. Only the one prepared statement whose binding changed is reprepared. >> > > > Thanks. Now this becomes weirder. I put breakpoints on all the locations > you mentioned and they were activated precisely as expected. When the > initial database is created, the breakpoints hit, but are not hit during > the actual load process. Yet, the first while condition in sqlite3_step: > > while( (rc = sqlite3Step(v))==SQLITE_SCHEMA > && cnt++ < SQLITE_MAX_SCHEMA_RETRY > && (rc2 = rc = sqlite3Reprepare(v))==SQLITE_OK ){ > sqlite3_reset(pStmt); > assert( v->expired==0 ); > } > > is triggering sqlite3Reprepare like clockwork. So, given that none of the > listed conditions are occurring, what else could be causing sqlite3Step to > return SQLITE_SCHEMA? > Ok. It's NOT triggering sqlite3Reprepare like clockwork. I added a function to allow me to check the return value and sqlite3Reprepare is being called an appropriate number of times. So we're back to the original question, "why is sqlite3Parser calling _malloc so many times?" I have an idea of how to determine if any specific queries are to blame, but I have to work on something unrelated this morning. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 19 Jan 2012, at 1:25pm, John Elrick wrote: > is triggering sqlite3Reprepare like clockwork. So, given that none of the > listed conditions are occurring, what else could be causing sqlite3Step to > return SQLITE_SCHEMA? It warms my heart to follow this wonderful technical detective story. Simon. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 8:15 AM, Richard Hipp wrote: > On Thu, Jan 19, 2012 at 8:10 AM, John Elrick >wrote: > > > > > I've been reading through the code. Do I understand correctly that if > one > > prepared statement binding is changed in such a way as may influence the > > choice of the query plan that all the prepared statements for that > database > > connection are flagged for being re-prepared? > > > > > No. Only the one prepared statement whose binding changed is reprepared. > Thanks. Now this becomes weirder. I put breakpoints on all the locations you mentioned and they were activated precisely as expected. When the initial database is created, the breakpoints hit, but are not hit during the actual load process. Yet, the first while condition in sqlite3_step: while( (rc = sqlite3Step(v))==SQLITE_SCHEMA && cnt++ < SQLITE_MAX_SCHEMA_RETRY && (rc2 = rc = sqlite3Reprepare(v))==SQLITE_OK ){ sqlite3_reset(pStmt); assert( v->expired==0 ); } is triggering sqlite3Reprepare like clockwork. So, given that none of the listed conditions are occurring, what else could be causing sqlite3Step to return SQLITE_SCHEMA? ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 8:10 AM, John Elrick wrote: > > I've been reading through the code. Do I understand correctly that if one > prepared statement binding is changed in such a way as may influence the > choice of the query plan that all the prepared statements for that database > connection are flagged for being re-prepared? > > No. Only the one prepared statement whose binding changed is reprepared. > > SQLITE_PRIVATE void sqlite3ExpirePreparedStatements(sqlite3 *db){ > Vdbe *p; > for(p = db->pVdbe; p; p=p->pNext){ >p->expired = 1; > } > } > > > > > > > > > > > > > > > On Thu, Jan 19, 2012 at 7:45 AM, Richard Hipp wrote: > > > > > > > On Thu, Jan 19, 2012 at 7:41 AM, John Elrick < > john.elr...@fenestra.com > > > > >wrote: > > > > > > > > > Question: > > > > > > > > > > If a query has already been prepared with sqlite3_prepare_v2, why > > would > > > > > sqlite3_step need to call sqlite3Prepare, which in turn calls > > > > > sqlite3RunParser? > > > > > > > > > > > > > Because the database schema changed. Or because you ran ATTACH or > > > VACUUM, > > > > either of which could potential change the bytecode necessary to run > > the > > > > statement. Or, because you changed the authorization callback. > > > > > > > > > > > > > > > > > ___ > > > > > sqlite-users mailing list > > > > > sqlite-users@sqlite.org > > > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > > > > > > > > > > > -- > > > > D. Richard Hipp > > > > d...@sqlite.org > > > > ___ > > > > sqlite-users mailing list > > > > sqlite-users@sqlite.org > > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > > > > > > -- > > > John Elrick > > > Fenestra Technologies > > > 540-868-1377 > > > ___ > > > sqlite-users mailing list > > > sqlite-users@sqlite.org > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > -- > > D. Richard Hipp > > d...@sqlite.org > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 8:03 AM, Richard Hipp wrote: > On Thu, Jan 19, 2012 at 7:51 AM, John Elrick >wrote: > > > Interesting: > > > > 1. There are no database schema changes occurring after the system is > fully > > initialized > > 2. There are no ATTACHed databases (we checked that earlier) > > 3. There are no calls to VACUUM > > 4. As far as I am aware, there are no changes to any callbacks after the > > system is fully initialized. > > > > I believe your earlier note is pointing us in the right direction. > > Examining my call stacks, it appears that the query is being reparsed on > > every call to step. The question is, why? Did any of these conditions > > change between 3.6.17 and 3.7.9? Maybe we are doing something that is > > unintentionally triggering the re-parse which did not do so in the > earlier > > version. > > > > > Also: Changing a bound parameter on the right-hand side of a LIKE or GLOB > operator forces a reprepare of that one statement, so that the query > optimizer can determine if the new value meets certain criteria for > optimization. > > Try setting a breakpoint on sqlite3ExpirePreparedStatements() to see what > you find. Also, on these lines to check for statement expiration due to > variable rebinding: > >http://www.sqlite.org/src/artifact/3662b6a468a2?ln=1024 >http://www.sqlite.org/src/artifact/3662b6a468a2?ln=129 > > > I've been reading through the code. Do I understand correctly that if one prepared statement binding is changed in such a way as may influence the choice of the query plan that all the prepared statements for that database connection are flagged for being re-prepared? SQLITE_PRIVATE void sqlite3ExpirePreparedStatements(sqlite3 *db){ Vdbe *p; for(p = db->pVdbe; p; p=p->pNext){ p->expired = 1; } } > > > > > > On Thu, Jan 19, 2012 at 7:45 AM, Richard Hipp wrote: > > > > > On Thu, Jan 19, 2012 at 7:41 AM, John Elrick > > >wrote: > > > > > > > Question: > > > > > > > > If a query has already been prepared with sqlite3_prepare_v2, why > would > > > > sqlite3_step need to call sqlite3Prepare, which in turn calls > > > > sqlite3RunParser? > > > > > > > > > > Because the database schema changed. Or because you ran ATTACH or > > VACUUM, > > > either of which could potential change the bytecode necessary to run > the > > > statement. Or, because you changed the authorization callback. > > > > > > > > > > > > > ___ > > > > sqlite-users mailing list > > > > sqlite-users@sqlite.org > > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > > > > > > -- > > > D. Richard Hipp > > > d...@sqlite.org > > > ___ > > > sqlite-users mailing list > > > sqlite-users@sqlite.org > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > -- > > John Elrick > > Fenestra Technologies > > 540-868-1377 > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 7:51 AM, John Elrick wrote: > Interesting: > > 1. There are no database schema changes occurring after the system is fully > initialized > 2. There are no ATTACHed databases (we checked that earlier) > 3. There are no calls to VACUUM > 4. As far as I am aware, there are no changes to any callbacks after the > system is fully initialized. > > I believe your earlier note is pointing us in the right direction. > Examining my call stacks, it appears that the query is being reparsed on > every call to step. The question is, why? Did any of these conditions > change between 3.6.17 and 3.7.9? Maybe we are doing something that is > unintentionally triggering the re-parse which did not do so in the earlier > version. > > Also: Changing a bound parameter on the right-hand side of a LIKE or GLOB operator forces a reprepare of that one statement, so that the query optimizer can determine if the new value meets certain criteria for optimization. Try setting a breakpoint on sqlite3ExpirePreparedStatements() to see what you find. Also, on these lines to check for statement expiration due to variable rebinding: http://www.sqlite.org/src/artifact/3662b6a468a2?ln=1024 http://www.sqlite.org/src/artifact/3662b6a468a2?ln=129 > On Thu, Jan 19, 2012 at 7:45 AM, Richard Hipp wrote: > > > On Thu, Jan 19, 2012 at 7:41 AM, John Elrick > >wrote: > > > > > Question: > > > > > > If a query has already been prepared with sqlite3_prepare_v2, why would > > > sqlite3_step need to call sqlite3Prepare, which in turn calls > > > sqlite3RunParser? > > > > > > > Because the database schema changed. Or because you ran ATTACH or > VACUUM, > > either of which could potential change the bytecode necessary to run the > > statement. Or, because you changed the authorization callback. > > > > > > > > > ___ > > > sqlite-users mailing list > > > sqlite-users@sqlite.org > > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > > > > > > -- > > D. Richard Hipp > > d...@sqlite.org > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Interesting: 1. There are no database schema changes occurring after the system is fully initialized 2. There are no ATTACHed databases (we checked that earlier) 3. There are no calls to VACUUM 4. As far as I am aware, there are no changes to any callbacks after the system is fully initialized. I believe your earlier note is pointing us in the right direction. Examining my call stacks, it appears that the query is being reparsed on every call to step. The question is, why? Did any of these conditions change between 3.6.17 and 3.7.9? Maybe we are doing something that is unintentionally triggering the re-parse which did not do so in the earlier version. On Thu, Jan 19, 2012 at 7:45 AM, Richard Hipp wrote: > On Thu, Jan 19, 2012 at 7:41 AM, John Elrick >wrote: > > > Question: > > > > If a query has already been prepared with sqlite3_prepare_v2, why would > > sqlite3_step need to call sqlite3Prepare, which in turn calls > > sqlite3RunParser? > > > > Because the database schema changed. Or because you ran ATTACH or VACUUM, > either of which could potential change the bytecode necessary to run the > statement. Or, because you changed the authorization callback. > > > > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Thu, Jan 19, 2012 at 7:41 AM, John Elrick wrote: > Question: > > If a query has already been prepared with sqlite3_prepare_v2, why would > sqlite3_step need to call sqlite3Prepare, which in turn calls > sqlite3RunParser? > Because the database schema changed. Or because you ran ATTACH or VACUUM, either of which could potential change the bytecode necessary to run the statement. Or, because you changed the authorization callback. > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Question: If a query has already been prepared with sqlite3_prepare_v2, why would sqlite3_step need to call sqlite3Prepare, which in turn calls sqlite3RunParser? ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Wed, Jan 18, 2012 at 4:32 PM, Richard Hipp wrote: > On Wed, Jan 18, 2012 at 4:30 PM, John Elrick >wrote: > > > I made one more stab and narrowed down the mallocs to this call: > > > > Count:119,133 = 'sqlite3Parser_lt_YYNSTATEpYYNRULE(12) > > sqlite3Parser(11) > > sqlite3RunParser(10) > > sqlite3Prepare(9) > > sqlite3_prepare(8) > > sqlite3_exec_inner_loop_invoke_callback(7) > > sqlite3_exec_outer_while(6) > > sqlite3_exec(5) > > sqlite3Parser_lt_YYNSTATEpYYNRULE(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0)' > > > > /**CS_ID**/ > fenestra_sqlite3_push(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); > > yy_reduce(yypParser,yyact-YYNSTATE); > > /**CS_ID**/ fenestra_sqlite3_pop(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); > > > > I started looking at yy_reduce, but it looks machine generated. If you > > give me some direction I'll see if I can narrow it down further. > > > > Can you print out the SQL that is being parsed when this malloc is called? > > I'll try to get some examples tomorrow. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Wed, Jan 18, 2012 at 4:30 PM, John Elrick wrote: > I made one more stab and narrowed down the mallocs to this call: > > Count:119,133 = 'sqlite3Parser_lt_YYNSTATEpYYNRULE(12) > sqlite3Parser(11) > sqlite3RunParser(10) > sqlite3Prepare(9) > sqlite3_prepare(8) > sqlite3_exec_inner_loop_invoke_callback(7) > sqlite3_exec_outer_while(6) > sqlite3_exec(5) > sqlite3Parser_lt_YYNSTATEpYYNRULE(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0)' > > /**CS_ID**/ fenestra_sqlite3_push(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); > yy_reduce(yypParser,yyact-YYNSTATE); > /**CS_ID**/ fenestra_sqlite3_pop(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); > > I started looking at yy_reduce, but it looks machine generated. If you > give me some direction I'll see if I can narrow it down further. > Can you print out the SQL that is being parsed when this malloc is called? > > > > On Wed, Jan 18, 2012 at 4:02 PM, John Elrick >wrote: > > > Whatever is happening, it appears I can only reproduce it under these > > circumstances. I'll continue digging into the procedure tomorrow to see > if > > I can narrow down where this is coming from. > > > > > > On Wed, Jan 18, 2012 at 3:54 PM, John Elrick >wrote: > > > >> FYI, I traced the number of calls to sqlite3ResetInternalSchema() on a > >> smaller set of data. It appears that it isn't the culprit. > >> > >> Total mallocs: 148,156 > >> Total calls to sqlite3ResetInternalSchema(): 63 > >> > >> > >> > >> On Wed, Jan 18, 2012 at 3:41 PM, John Elrick >wrote: > >> > >>> What else could trigger a call to sqlite3ResetInternalSchema()? I'm > >>> getting a clear breakpoint tracing back to such innocuous calls as > >>> _sqlite3_step. > >>> > >>> > >>> > >>> > >>> On Wed, Jan 18, 2012 at 3:31 PM, Richard Hipp wrote: > >>> > On Wed, Jan 18, 2012 at 3:12 PM, John Elrick < > john.elr...@fenestra.com > >wrote: > > > > > Total times _malloc called in test: 69,859,114 > > > > Times calling _malloc: 57,679,282 > > sqlite3Parser(10) > > sqlite3RunParser(9) > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0 > > > > It looks like you might be doing something that is forcing SQLite to > constantly reparse the schema. > > * CREATE or DROP statements > * Registering new collating sequences > * Registering new application-defined functions > * ATTACH > * VACUUM > > Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out > what > is > making the schema be reparsed so much. > > > > > > Times calling _malloc: 2,775,682 > > sqlite3RunParser(9) > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > > > Times calling _malloc: 2,775,682 > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > > > Times calling _malloc: 2,092,350 > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > >>> > >>> > >>> > >>> -- > >>> John Elrick > >>> Fenestra Technologies > >>> 540-868-1377 > >>> > >>> > >> > >> > >> -- > >> John Elrick > >> Fenestra Technologies > >> 540-868-1377 > >> > >> > > > > > > -- > > John Elrick > > Fenestra Technologies > > 540-868-1377 > > > > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I made one more stab and narrowed down the mallocs to this call: Count:119,133 = 'sqlite3Parser_lt_YYNSTATEpYYNRULE(12) sqlite3Parser(11) sqlite3RunParser(10) sqlite3Prepare(9) sqlite3_prepare(8) sqlite3_exec_inner_loop_invoke_callback(7) sqlite3_exec_outer_while(6) sqlite3_exec(5) sqlite3Parser_lt_YYNSTATEpYYNRULE(4) sqlite3Parser(3) sqlite3RunParser(2) sqlite3Prepare(1) sqlite3_step(0)' /**CS_ID**/ fenestra_sqlite3_push(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); yy_reduce(yypParser,yyact-YYNSTATE); /**CS_ID**/ fenestra_sqlite3_pop(csid_sqlite3Parser_lt_YYNSTATEpYYNRULE); I started looking at yy_reduce, but it looks machine generated. If you give me some direction I'll see if I can narrow it down further. On Wed, Jan 18, 2012 at 4:02 PM, John Elrick wrote: > Whatever is happening, it appears I can only reproduce it under these > circumstances. I'll continue digging into the procedure tomorrow to see if > I can narrow down where this is coming from. > > > On Wed, Jan 18, 2012 at 3:54 PM, John Elrick wrote: > >> FYI, I traced the number of calls to sqlite3ResetInternalSchema() on a >> smaller set of data. It appears that it isn't the culprit. >> >> Total mallocs: 148,156 >> Total calls to sqlite3ResetInternalSchema(): 63 >> >> >> >> On Wed, Jan 18, 2012 at 3:41 PM, John Elrick wrote: >> >>> What else could trigger a call to sqlite3ResetInternalSchema()? I'm >>> getting a clear breakpoint tracing back to such innocuous calls as >>> _sqlite3_step. >>> >>> >>> >>> >>> On Wed, Jan 18, 2012 at 3:31 PM, Richard Hipp wrote: >>> On Wed, Jan 18, 2012 at 3:12 PM, John Elrick >>> >wrote: > > Total times _malloc called in test: 69,859,114 > > Times calling _malloc: 57,679,282 > sqlite3Parser(10) > sqlite3RunParser(9) > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0 > It looks like you might be doing something that is forcing SQLite to constantly reparse the schema. * CREATE or DROP statements * Registering new collating sequences * Registering new application-defined functions * ATTACH * VACUUM Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out what is making the schema be reparsed so much. > > Times calling _malloc: 2,775,682 > sqlite3RunParser(9) > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > > Times calling _malloc: 2,775,682 > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > > Times calling _malloc: 2,092,350 > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >>> >>> >>> >>> -- >>> John Elrick >>> Fenestra Technologies >>> 540-868-1377 >>> >>> >> >> >> -- >> John Elrick >> Fenestra Technologies >> 540-868-1377 >> >> > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Whatever is happening, it appears I can only reproduce it under these circumstances. I'll continue digging into the procedure tomorrow to see if I can narrow down where this is coming from. On Wed, Jan 18, 2012 at 3:54 PM, John Elrick wrote: > FYI, I traced the number of calls to sqlite3ResetInternalSchema() on a > smaller set of data. It appears that it isn't the culprit. > > Total mallocs: 148,156 > Total calls to sqlite3ResetInternalSchema(): 63 > > > > On Wed, Jan 18, 2012 at 3:41 PM, John Elrick wrote: > >> What else could trigger a call to sqlite3ResetInternalSchema()? I'm >> getting a clear breakpoint tracing back to such innocuous calls as >> _sqlite3_step. >> >> >> >> >> On Wed, Jan 18, 2012 at 3:31 PM, Richard Hipp wrote: >> >>> On Wed, Jan 18, 2012 at 3:12 PM, John Elrick >> >wrote: >>> >>> > >>> > Total times _malloc called in test: 69,859,114 >>> > >>> > Times calling _malloc: 57,679,282 >>> > sqlite3Parser(10) >>> > sqlite3RunParser(9) >>> > sqlite3Prepare(8) >>> > sqlite3_prepare(7) >>> > sqlite3_exec_inner_loop_invoke_callback(6) >>> > sqlite3_exec_outer_while(5) >>> > sqlite3_exec(4) >>> > sqlite3Parser(3) >>> > sqlite3RunParser(2) >>> > sqlite3Prepare(1) >>> > sqlite3_step(0 >>> > >>> >>> It looks like you might be doing something that is forcing SQLite to >>> constantly reparse the schema. >>> >>> * CREATE or DROP statements >>> * Registering new collating sequences >>> * Registering new application-defined functions >>> * ATTACH >>> * VACUUM >>> >>> Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out what >>> is >>> making the schema be reparsed so much. >>> >>> >>> > >>> > Times calling _malloc: 2,775,682 >>> > sqlite3RunParser(9) >>> > sqlite3Prepare(8) >>> > sqlite3_prepare(7) >>> > sqlite3_exec_inner_loop_invoke_callback(6) >>> > sqlite3_exec_outer_while(5) >>> > sqlite3_exec(4) >>> > sqlite3Parser(3) >>> > sqlite3RunParser(2) >>> > sqlite3Prepare(1) >>> > sqlite3_step(0) >>> > >>> > Times calling _malloc: 2,775,682 >>> > sqlite3Prepare(8) >>> > sqlite3_prepare(7) >>> > sqlite3_exec_inner_loop_invoke_callback(6) >>> > sqlite3_exec_outer_while(5) >>> > sqlite3_exec(4) >>> > sqlite3Parser(3) >>> > sqlite3RunParser(2) >>> > sqlite3Prepare(1) >>> > sqlite3_step(0) >>> > >>> > Times calling _malloc: 2,092,350 >>> > sqlite3Parser(3) >>> > sqlite3RunParser(2) >>> > sqlite3Prepare(1) >>> > sqlite3_step(0) >>> > ___ >>> > sqlite-users mailing list >>> > sqlite-users@sqlite.org >>> > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >>> > >>> >>> >>> >>> -- >>> D. Richard Hipp >>> d...@sqlite.org >>> ___ >>> sqlite-users mailing list >>> sqlite-users@sqlite.org >>> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >>> >> >> >> >> -- >> John Elrick >> Fenestra Technologies >> 540-868-1377 >> >> > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
FYI, I traced the number of calls to sqlite3ResetInternalSchema() on a smaller set of data. It appears that it isn't the culprit. Total mallocs: 148,156 Total calls to sqlite3ResetInternalSchema(): 63 On Wed, Jan 18, 2012 at 3:41 PM, John Elrick wrote: > What else could trigger a call to sqlite3ResetInternalSchema()? I'm > getting a clear breakpoint tracing back to such innocuous calls as > _sqlite3_step. > > > > > On Wed, Jan 18, 2012 at 3:31 PM, Richard Hipp wrote: > >> On Wed, Jan 18, 2012 at 3:12 PM, John Elrick > >wrote: >> >> > >> > Total times _malloc called in test: 69,859,114 >> > >> > Times calling _malloc: 57,679,282 >> > sqlite3Parser(10) >> > sqlite3RunParser(9) >> > sqlite3Prepare(8) >> > sqlite3_prepare(7) >> > sqlite3_exec_inner_loop_invoke_callback(6) >> > sqlite3_exec_outer_while(5) >> > sqlite3_exec(4) >> > sqlite3Parser(3) >> > sqlite3RunParser(2) >> > sqlite3Prepare(1) >> > sqlite3_step(0 >> > >> >> It looks like you might be doing something that is forcing SQLite to >> constantly reparse the schema. >> >> * CREATE or DROP statements >> * Registering new collating sequences >> * Registering new application-defined functions >> * ATTACH >> * VACUUM >> >> Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out what is >> making the schema be reparsed so much. >> >> >> > >> > Times calling _malloc: 2,775,682 >> > sqlite3RunParser(9) >> > sqlite3Prepare(8) >> > sqlite3_prepare(7) >> > sqlite3_exec_inner_loop_invoke_callback(6) >> > sqlite3_exec_outer_while(5) >> > sqlite3_exec(4) >> > sqlite3Parser(3) >> > sqlite3RunParser(2) >> > sqlite3Prepare(1) >> > sqlite3_step(0) >> > >> > Times calling _malloc: 2,775,682 >> > sqlite3Prepare(8) >> > sqlite3_prepare(7) >> > sqlite3_exec_inner_loop_invoke_callback(6) >> > sqlite3_exec_outer_while(5) >> > sqlite3_exec(4) >> > sqlite3Parser(3) >> > sqlite3RunParser(2) >> > sqlite3Prepare(1) >> > sqlite3_step(0) >> > >> > Times calling _malloc: 2,092,350 >> > sqlite3Parser(3) >> > sqlite3RunParser(2) >> > sqlite3Prepare(1) >> > sqlite3_step(0) >> > ___ >> > sqlite-users mailing list >> > sqlite-users@sqlite.org >> > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >> > >> >> >> >> -- >> D. Richard Hipp >> d...@sqlite.org >> ___ >> sqlite-users mailing list >> sqlite-users@sqlite.org >> http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users >> > > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
What else could trigger a call to sqlite3ResetInternalSchema()? I'm getting a clear breakpoint tracing back to such innocuous calls as _sqlite3_step. On Wed, Jan 18, 2012 at 3:31 PM, Richard Hipp wrote: > On Wed, Jan 18, 2012 at 3:12 PM, John Elrick >wrote: > > > > > Total times _malloc called in test: 69,859,114 > > > > Times calling _malloc: 57,679,282 > > sqlite3Parser(10) > > sqlite3RunParser(9) > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0 > > > > It looks like you might be doing something that is forcing SQLite to > constantly reparse the schema. > > * CREATE or DROP statements > * Registering new collating sequences > * Registering new application-defined functions > * ATTACH > * VACUUM > > Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out what is > making the schema be reparsed so much. > > > > > > Times calling _malloc: 2,775,682 > > sqlite3RunParser(9) > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > > > Times calling _malloc: 2,775,682 > > sqlite3Prepare(8) > > sqlite3_prepare(7) > > sqlite3_exec_inner_loop_invoke_callback(6) > > sqlite3_exec_outer_while(5) > > sqlite3_exec(4) > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > > > Times calling _malloc: 2,092,350 > > sqlite3Parser(3) > > sqlite3RunParser(2) > > sqlite3Prepare(1) > > sqlite3_step(0) > > ___ > > sqlite-users mailing list > > sqlite-users@sqlite.org > > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > > > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Wed, Jan 18, 2012 at 3:12 PM, John Elrick wrote: > > Total times _malloc called in test: 69,859,114 > > Times calling _malloc: 57,679,282 > sqlite3Parser(10) > sqlite3RunParser(9) > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0 > It looks like you might be doing something that is forcing SQLite to constantly reparse the schema. * CREATE or DROP statements * Registering new collating sequences * Registering new application-defined functions * ATTACH * VACUUM Maybe set a breakpoint on sqlite3ResetInternalSchema() to find out what is making the schema be reparsed so much. > > Times calling _malloc: 2,775,682 > sqlite3RunParser(9) > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > > Times calling _malloc: 2,775,682 > sqlite3Prepare(8) > sqlite3_prepare(7) > sqlite3_exec_inner_loop_invoke_callback(6) > sqlite3_exec_outer_while(5) > sqlite3_exec(4) > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > > Times calling _malloc: 2,092,350 > sqlite3Parser(3) > sqlite3RunParser(2) > sqlite3Prepare(1) > sqlite3_step(0) > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I could not use any of the proffered tools for several reasons. After an inspiration yesterday, I dusted off my C programming skills and started hacking a pseudo-call stack system into SQLite3.c. I've put the statistics below for the top couple of call stacks. Total times _malloc called in test: 69,859,114 Times calling _malloc: 57,679,282 sqlite3Parser(10) sqlite3RunParser(9) sqlite3Prepare(8) sqlite3_prepare(7) sqlite3_exec_inner_loop_invoke_callback(6) sqlite3_exec_outer_while(5) sqlite3_exec(4) sqlite3Parser(3) sqlite3RunParser(2) sqlite3Prepare(1) sqlite3_step(0 Times calling _malloc: 2,775,682 sqlite3RunParser(9) sqlite3Prepare(8) sqlite3_prepare(7) sqlite3_exec_inner_loop_invoke_callback(6) sqlite3_exec_outer_while(5) sqlite3_exec(4) sqlite3Parser(3) sqlite3RunParser(2) sqlite3Prepare(1) sqlite3_step(0) Times calling _malloc: 2,775,682 sqlite3Prepare(8) sqlite3_prepare(7) sqlite3_exec_inner_loop_invoke_callback(6) sqlite3_exec_outer_while(5) sqlite3_exec(4) sqlite3Parser(3) sqlite3RunParser(2) sqlite3Prepare(1) sqlite3_step(0) Times calling _malloc: 2,092,350 sqlite3Parser(3) sqlite3RunParser(2) sqlite3Prepare(1) sqlite3_step(0) ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Pavel Ivanov wrote, On 1/17/2012 9:42 AM: I attempted all of the above and the call stacks do not change. That leads me to one of two conclusions: 1. The call stacks are inaccurate 2. There is some side effect which is causing malloc to be called inside of a procedure which should not be calling malloc. I've posted an update to my mistaken realloc listing. I may have to take a break to see if I can think of another approach to the problem. Maybe you should try to get stack traces from different debugger? E.g. try WinDbg or even Visual Studio. I believe IDE don't have to be able to understand source code in order to understand debugging information included into binary and show you stack traces. BTW you can try gdb although I'm not sure there's pre-compiled version of gdb for Windows. Cygwin has gdb. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
> I attempted all of the above and the call stacks do not change. That leads > me to one of two conclusions: > > 1. The call stacks are inaccurate > 2. There is some side effect which is causing malloc to be called inside > of a procedure which should not be calling malloc. > > I've posted an update to my mistaken realloc listing. I may have to take a > break to see if I can think of another approach to the problem. Maybe you should try to get stack traces from different debugger? E.g. try WinDbg or even Visual Studio. I believe IDE don't have to be able to understand source code in order to understand debugging information included into binary and show you stack traces. BTW you can try gdb although I'm not sure there's pre-compiled version of gdb for Windows. Pavel ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 8:05 PM, John Elrick wrote: > > > On Mon, Jan 16, 2012 at 5:31 PM, Richard Hipp wrote: > >> On Mon, Jan 16, 2012 at 5:13 PM, John Elrick > >wrote: >> >> > I did this trace through the Delphi IDE and hand copied the call stack. >> > Unfortunately, I can't give you line numbers, although I could go back >> and >> > give you hex offsets from the start of the procedures. These are >> literally >> > the first seven call stacks from _malloc after I initiate the trace. >> I'm >> > noticing a pattern. Hopefully 1) the information from the IDE is >> accurate >> > and 2) this helps. The trace reads from bottom to top. >> > >> >> I do not think the information below is correct. For example, at no point >> does sqlite3_db_status() ever call malloc(). Similarly, sqlite3_free() >> never calls sqlite3_db_status(). And really - why would sqlite3_free() >> ever call malloc() - that makes no sense. >> >> I'm thinking the Delphi IDE is not giving you good information here, which >> is too bad since we could have really used the information if it had been >> good. >> >> Are there any options to Delphi that can give you better diagnostics? Do >> you need to recompile SQLite without optimization and including the -g >> option? >> >> > I can try that approach with BCC. I was concerned that the IDE would be > getting inaccurate information from the .OBJ. Crossing into a pre-complied > library can be tricky. > I attempted all of the above and the call stacks do not change. That leads me to one of two conclusions: 1. The call stacks are inaccurate 2. There is some side effect which is causing malloc to be called inside of a procedure which should not be calling malloc. I've posted an update to my mistaken realloc listing. I may have to take a break to see if I can think of another approach to the problem. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:36 PM, Richard Hipp wrote: > On Mon, Jan 16, 2012 at 5:31 PM, John Elrick >wrote: > > SNIP > This is very curious and perhaps a useful clue. SQLite does call > SNIP It is a clue that I need a break. While updating the counters to allow for nil pointers, I noticed I had done something stupid in the accumulators for realloc. Fixed below: Application: Surveyor.exe Sqlite version:3.7.9 Date/Time: 01/17/2012 08:17:22 Memory Used: 7,905,536 (max 8,582,104) bytes Page Cache Used: 0 (max 0) pages Page Cache Overflow: 6,910,576 (max 6,911,600) bytes Number of Scratch Allocations Used:0 (max 0) Scratch Overflow: 0 (max 24,880) bytes Largest Allocation:500,042 bytes Parser Stack: 0 Largest Pcache Allocation: 4,232 bytes Largest Scratch Allocation:24,880 bytes Number of Outstanding Allocations: 5,835 (max 6,499) Lookaside Slots Used: 500 (max 500) Pager Heap Usage: 6,873,408 bytes Schema Heap Usage: 39,560 bytes Statement Heap/Lookaside Usage:806,592 bytes Successful lookaside attempts: 4,888 Lookaside failures due to size:3,782,307 Lookaside failures due to OOM: 4,090,019 Page cache hits: 2,585,425 Page cache misses: 0 Cumulative Allocated Memory: 932,315,928 Count of _malloc Calls:69,859,114 Cumulative Reallocated Memory: 226,385,120 Cumulative Reallocated Memory where nil: 0 Count of _realloc Calls: 776,372 Count of _realloc Calls where nil: 0 Count of _free Calls: 69,857,292 Cumulative _mallocs by size <= 1kb:1,118,058,528 bytes (63,640,300 count) 1kb to 4kb:3,836,490,296 bytes (6,197,060 count) 4bk to 8kb:47,800,672 bytes (11,571 count) 8bk to 16kb: 597,016 bytes (46 count) 16bk to 32kb: 224,272,704 bytes (10,136 count) 32bk to 64kb: 64,008 bytes (1 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs by size <= 1kb:189,468,416 bytes (759,348 count) 1kb to 4kb:36,904,328 bytes (17,022 count) 4bk to 8kb:12,376 bytes (2 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) Cumulative _reallocs of nil pointers by size <= 1kb:0 bytes (0 count) 1kb to 4kb:0 bytes (0 count) 4bk to 8kb:0 bytes (0 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb: 0 bytes (0 count) 128kb to 256kb:0 bytes (0 count) 256kb to 512kb:0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb: 0 bytes (0 count) ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 11:47 PM, Max Vlasov wrote: > On Tue, Jan 17, 2012 at 5:05 AM, John Elrick >wrote: > > > > > > I can try that approach with BCC. I was concerned that the IDE would be > > getting inaccurate information from the .OBJ. Crossing into a > pre-complied > > library can be tricky. > > > > > As I recall,I could not make debug information compiled by bcc visible in > Delphi IDE, but everything will be ok if you make your code compatible with > fpc/lazarus. Besides the fact that you will be able to walk inside sqlite c > code and inspect the data (gdb is used), you will probably make your > software cross-platform. Besides, there is a library for lazarus/fpc > (developed by Ludo Brands and me) for inspecting stack calling paths with > whose memory blocks are allocated (similar to Valgrind tool). By the way, > Ludo did a great job with stack unwinding since I remember false positives > like ones mentioned here when calling chains were very strange and he had > to implement a sophisticated stack analysis for many real world examples > > Unfortunately getting our project (circa 500,000 lines including 3rd party) would require a massive conversion effort to compile under Lazarus. I've investigated it. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Tue, Jan 17, 2012 at 5:05 AM, John Elrick wrote: > > > I can try that approach with BCC. I was concerned that the IDE would be > getting inaccurate information from the .OBJ. Crossing into a pre-complied > library can be tricky. > > As I recall,I could not make debug information compiled by bcc visible in Delphi IDE, but everything will be ok if you make your code compatible with fpc/lazarus. Besides the fact that you will be able to walk inside sqlite c code and inspect the data (gdb is used), you will probably make your software cross-platform. Besides, there is a library for lazarus/fpc (developed by Ludo Brands and me) for inspecting stack calling paths with whose memory blocks are allocated (similar to Valgrind tool). By the way, Ludo did a great job with stack unwinding since I remember false positives like ones mentioned here when calling chains were very strange and he had to implement a sophisticated stack analysis for many real world examples Max ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:31 PM, Richard Hipp wrote: > On Mon, Jan 16, 2012 at 5:13 PM, John Elrick >wrote: > > > I did this trace through the Delphi IDE and hand copied the call stack. > > Unfortunately, I can't give you line numbers, although I could go back > and > > give you hex offsets from the start of the procedures. These are > literally > > the first seven call stacks from _malloc after I initiate the trace. I'm > > noticing a pattern. Hopefully 1) the information from the IDE is > accurate > > and 2) this helps. The trace reads from bottom to top. > > > > I do not think the information below is correct. For example, at no point > does sqlite3_db_status() ever call malloc(). Similarly, sqlite3_free() > never calls sqlite3_db_status(). And really - why would sqlite3_free() > ever call malloc() - that makes no sense. > > I'm thinking the Delphi IDE is not giving you good information here, which > is too bad since we could have really used the information if it had been > good. > > Are there any options to Delphi that can give you better diagnostics? Do > you need to recompile SQLite without optimization and including the -g > option? > > I can try that approach with BCC. I was concerned that the IDE would be getting inaccurate information from the .OBJ. Crossing into a pre-complied library can be tricky. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I will adjust the realloc tests tomorrow and let you know. The two routines are unique in the Delphi library unit. Thanks again for your time and efforts. On Mon, Jan 16, 2012 at 5:36 PM, Richard Hipp wrote: > On Mon, Jan 16, 2012 at 5:31 PM, John Elrick >wrote: > > > > > I don't know if the calls to _realloc will help also, but I've added > > tracing for those also. My updated output: > > Cumulative _mallocs by size > > <= 1kb: 1,118,058,528 bytes (63,640,300 > > count) > > 1kb to 4kb: 3,836,490,296 bytes (6,197,060 > count) > > 4bk to 8kb: 47,800,672 bytes (11,571 count) > > 8bk to 16kb: 597,016 bytes (46 count) > > 16bk to 32kb: 224,272,704 bytes (10,136 count) > > 32bk to 64kb: 64,008 bytes (1 count)Cumulative > > _reallocs by size > > <= 1kb: 1,117,392,608 bytes (63,637,756 > > count) > > 1kb to 4kb: 3,836,372,120 bytes (6,196,954 > count) > > 4bk to 8kb: 30,800 bytes (6 count) > > 8bk to 16kb: 0 bytes (0 count) > > > > This is very curious and perhaps a useful clue. SQLite does call > realloc(), but not that often. And yet here we see realloc() being called > almost as much as malloc(). I'll investigate further on this end. In the > meantime, are you *certain* that the numbers above are correct? Please > register as a malloc() any call to realloc(A,B) where A is NULL. With that > change, are the numbers above still the same? > > > > -- > D. Richard Hipp > d...@sqlite.org > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:31 PM, John Elrick wrote: > > I don't know if the calls to _realloc will help also, but I've added > tracing for those also. My updated output: > Cumulative _mallocs by size > <= 1kb: 1,118,058,528 bytes (63,640,300 > count) > 1kb to 4kb: 3,836,490,296 bytes (6,197,060 count) > 4bk to 8kb: 47,800,672 bytes (11,571 count) > 8bk to 16kb: 597,016 bytes (46 count) > 16bk to 32kb: 224,272,704 bytes (10,136 count) > 32bk to 64kb: 64,008 bytes (1 count)Cumulative > _reallocs by size > <= 1kb: 1,117,392,608 bytes (63,637,756 > count) > 1kb to 4kb: 3,836,372,120 bytes (6,196,954 count) > 4bk to 8kb: 30,800 bytes (6 count) > 8bk to 16kb: 0 bytes (0 count) > This is very curious and perhaps a useful clue. SQLite does call realloc(), but not that often. And yet here we see realloc() being called almost as much as malloc(). I'll investigate further on this end. In the meantime, are you *certain* that the numbers above are correct? Please register as a malloc() any call to realloc(A,B) where A is NULL. With that change, are the numbers above still the same? -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:13 PM, John Elrick wrote: > I did this trace through the Delphi IDE and hand copied the call stack. > Unfortunately, I can't give you line numbers, although I could go back and > give you hex offsets from the start of the procedures. These are literally > the first seven call stacks from _malloc after I initiate the trace. I'm > noticing a pattern. Hopefully 1) the information from the IDE is accurate > and 2) this helps. The trace reads from bottom to top. > I do not think the information below is correct. For example, at no point does sqlite3_db_status() ever call malloc(). Similarly, sqlite3_free() never calls sqlite3_db_status(). And really - why would sqlite3_free() ever call malloc() - that makes no sense. I'm thinking the Delphi IDE is not giving you good information here, which is too bad since we could have really used the information if it had been good. Are there any options to Delphi that can give you better diagnostics? Do you need to recompile SQLite without optimization and including the -g option? > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_backup_pagecount > _sqlite3_backup_pagecount > _sqlite3_column_decltype > _sqlite3_bind_text > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_free > _sqlite3_stmt_status > _sqlite3_stmt_status > _sqlite3_free_table > _sqlite3_free_table > _sqlite3_free_table > _sqlite3_exec > _sqlite3_exec > _sqlite3_prepare_v2 > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_stmt_status > _sqlite3_stmt_status > _sqlite3_free_table > _sqlite3_free_table > _sqlite3_free_table > _sqlite3_exec > _sqlite3_exec > _sqlite3_prepare_v2 > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free_table > _sqlite3_free_table > _sqlite3_exec > _sqlite3_exec > _sqlite3_prepare_v2 > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_free > _sqlite3_exec > _sqlite3_exec > _sqlite3_prepare_v2 > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_backup_pagecount > _sqlite3_stmt_status > _sqlite3_stmt_status > _squite3_reset > _sqlite3_step > > _malloc > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_db_status > _sqlite3_free > _sqlite3_free > _sqlite3_free > _sqlite3_stmt_status > _sqlite3_stmt_status > _squite3_reset > _sqlite3_step > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Richard, I don't know if the calls to _realloc will help also, but I've added tracing for those also. My updated output: Application: Surveyor.exe Sqlite version: 3.7.9 Date/Time:01/16/2012 17:20:58 Memory Used: 7,905,536 (max 8,582,104) bytes Page Cache Used: 0 (max 0) pages Page Cache Overflow: 6,910,576 (max 6,911,600) bytes Number of Scratch Allocations Used: 0 (max 0) Scratch Overflow: 0 (max 24,880) bytes Largest Allocation: 500,042 bytes Parser Stack: 0 Largest Pcache Allocation:4,232 bytes Largest Scratch Allocation: 24,880 bytes Number of Outstanding Allocations:5,835 (max 6,499) Lookaside Slots Used: 500 (max 500) Pager Heap Usage: 6,873,408 bytes Schema Heap Usage:39,560 bytes Statement Heap/Lookaside Usage: 806,592 bytes Successful lookaside attempts:4,888 Lookaside failures due to size: 3,782,307 Lookaside failures due to OOM:4,090,019 Page cache hits: 2,585,425 Page cache misses:0 Cumulative Allocated Memory: 932,315,928 Count of _malloc Calls: 69,859,114 Cumulative Reallocated Memory:931,150,680 Count of _realloc Calls: 69,856,395 Count of _free Calls: 69,857,292 Cumulative _mallocs by size <= 1kb: 1,118,058,528 bytes (63,640,300 count) 1kb to 4kb: 3,836,490,296 bytes (6,197,060 count) 4bk to 8kb: 47,800,672 bytes (11,571 count) 8bk to 16kb: 597,016 bytes (46 count) 16bk to 32kb: 224,272,704 bytes (10,136 count) 32bk to 64kb: 64,008 bytes (1 count) 64bk to 128kb:0 bytes (0 count) 128kb to 256kb: 0 bytes (0 count) 256kb to 512kb: 0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb:0 bytes (0 count) Cumulative _reallocs by size <= 1kb: 1,117,392,608 bytes (63,637,756 count) 1kb to 4kb: 3,836,372,120 bytes (6,196,954 count) 4bk to 8kb: 30,800 bytes (6 count) 8bk to 16kb: 0 bytes (0 count) 16bk to 32kb: 0 bytes (0 count) 32bk to 64kb: 0 bytes (0 count) 64bk to 128kb:0 bytes (0 count) 128kb to 256kb: 0 bytes (0 count) 256kb to 512kb: 0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb:0 bytes (0 count) ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:14 PM, Simon Slavin wrote: > > On 16 Jan 2012, at 9:37pm, John Elrick wrote: > > > Lacking the status interfaces for 3.6.17 I was forced to mark them as > > "interface not supported". Simon suggested I track the calls to _malloc, > > so I've added extensive tracing code. > > Those results are excellently detailed and make no sense to me at all. > Fortunately there are people on this list who know the internals of SQLite > far better than I do. Well done for getting that diagnostic to the point > you have. Thanks very much. You have no idea how much I appreciate that pat on the back (or maybe you do...) ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 16 Jan 2012, at 9:37pm, John Elrick wrote: > Lacking the status interfaces for 3.6.17 I was forced to mark them as > "interface not supported". Simon suggested I track the calls to _malloc, > so I've added extensive tracing code. Those results are excellently detailed and make no sense to me at all. Fortunately there are people on this list who know the internals of SQLite far better than I do. Well done for getting that diagnostic to the point you have. Simon. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
I did this trace through the Delphi IDE and hand copied the call stack. Unfortunately, I can't give you line numbers, although I could go back and give you hex offsets from the start of the procedures. These are literally the first seven call stacks from _malloc after I initiate the trace. I'm noticing a pattern. Hopefully 1) the information from the IDE is accurate and 2) this helps. The trace reads from bottom to top. _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_backup_pagecount _sqlite3_backup_pagecount _sqlite3_column_decltype _sqlite3_bind_text _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_free _sqlite3_stmt_status _sqlite3_stmt_status _sqlite3_free_table _sqlite3_free_table _sqlite3_free_table _sqlite3_exec _sqlite3_exec _sqlite3_prepare_v2 _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_stmt_status _sqlite3_stmt_status _sqlite3_free_table _sqlite3_free_table _sqlite3_free_table _sqlite3_exec _sqlite3_exec _sqlite3_prepare_v2 _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_free_table _sqlite3_free_table _sqlite3_exec _sqlite3_exec _sqlite3_prepare_v2 _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_free _sqlite3_exec _sqlite3_exec _sqlite3_prepare_v2 _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_backup_pagecount _sqlite3_stmt_status _sqlite3_stmt_status _squite3_reset _sqlite3_step _malloc _sqlite3_db_status _sqlite3_db_status _sqlite3_db_status _sqlite3_free _sqlite3_free _sqlite3_free _sqlite3_stmt_status _sqlite3_stmt_status _squite3_reset _sqlite3_step ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 4:37 PM, John Elrick wrote: > Sqlite version: 3.6.17 > Cumulative _mallocs by size > <= 1kb: 109,025,904 bytes (565,230 count) > 1kb to 4kb: 510,357,112 bytes (485,801 count) > 4bk to 8kb: 48,005,376 bytes (11,610 count) > > Sqlite version: 3.7.9 > Cumulative _mallocs by size > <= 1kb: 1,118,058,528 bytes (63,640,300 > count) > 1kb to 4kb: 3,836,490,296 bytes (6,197,060 count) > Clearly there are many more small mallocs happening with 3.7.9 than with 3.6.17. We just need to figure out why. Here's a suggestion: Run the program in a debugger and look at the stack trace every time a small malloc occurs.. Since the extra mallocs far outnumber the regular mallocs, chances are you'll find the place which is doing all of the extra mallocing pretty quickly. Please let us know where all these extra mallocs are coming from. If you can give me 6 or 12 different places from within SQLite where the extra mallocs are coming from, that will probably be a sufficient clue. -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
Addendum: This test was conducted using a full size test dataset. I had been using one that was an order of magnitude smaller for profiling before, but could use the full size for this test. On Mon, Jan 16, 2012 at 4:37 PM, John Elrick wrote: > Lacking the status interfaces for 3.6.17 I was forced to mark them as > "interface not supported". Simon suggested I track the calls to _malloc, > so I've added extensive tracing code. Here is the final output from the > two versions: > > Application: Surveyor.exe > Sqlite version: 3.6.17 > Date/Time:01/16/2012 16:32:18 > Memory Used: interface not supported > Page Cache Used: interface not supported > Page Cache Overflow: interface not supported > Number of Scratch Allocations Used: interface not supported > Scratch Overflow: interface not supported > Largest Allocation: interface not supported > Parser Stack: interface not supported > Largest Pcache Allocation:interface not supported > Largest Scratch Allocation: interface not supported > Number of Outstanding Allocations:interface not supported > Lookaside Slots Used: interface not supported > Pager Heap Usage: interface not supported > Schema Heap Usage:interface not supported > Statement Heap/Lookaside Usage: interface not supported > Successful lookaside attempts:interface not supported > Lookaside failures due to size: interface not supported > Lookaside failures due to OOM:interface not supported > Page cache hits: interface not supported > Page cache misses:interface not supported > Cumulative Allocated Memory: 892,318,312 > Count of _malloc Calls: 1,072,825 > Count of _free Calls: 1,070,971 > Cumulative _mallocs by size > <= 1kb: 109,025,904 bytes (565,230 count) > 1kb to 4kb: 510,357,112 bytes (485,801 count) > 4bk to 8kb: 48,005,376 bytes (11,610 count) > 8bk to 16kb: 605,208 bytes (47 count) > 16bk to 32kb: 224,272,704 bytes (10,136 count) > 32bk to 64kb: 52,008 bytes (1 count) > 64bk to 128kb:0 bytes (0 count) > 128kb to 256kb: 0 bytes (0 count) > 256kb to 512kb: 0 bytes (0 count) > 512kb to 1024kb: 0 bytes (0 count) > > 1mb:0 bytes (0 count) > > Application: Surveyor.exe > Sqlite version: 3.7.9 > Date/Time:01/16/2012 16:35:01 > Memory Used: 7,905,536 (max 8,582,104) bytes > Page Cache Used: 0 (max 0) pages > Page Cache Overflow: 6,910,576 (max 6,911,600) bytes > Number of Scratch Allocations Used: 0 (max 0) > Scratch Overflow: 0 (max 24,880) bytes > Largest Allocation: 500,042 bytes > Parser Stack: 0 > Largest Pcache Allocation:4,232 bytes > Largest Scratch Allocation: 24,880 bytes > Number of Outstanding Allocations:5,835 (max 6,499) > Lookaside Slots Used: 500 (max 500) > Pager Heap Usage: 6,873,408 bytes > Schema Heap Usage:39,560 bytes > Statement Heap/Lookaside Usage: 806,592 bytes > Successful lookaside attempts:4,888 > Lookaside failures due to size: 3,782,307 > Lookaside failures due to OOM:4,090,019 > Page cache hits: 2,585,425 > Page cache misses:0 > Cumulative Allocated Memory: 932,315,928 > Count of _malloc Calls: 69,859,114 > Count of _free Calls: 69,857,292 > Cumulative _mallocs by size > <= 1kb: 1,118,058,528 bytes (63,640,300 > count) > 1kb to 4kb: 3,836,490,296 bytes (6,197,060 count) > 4bk to 8kb: 47,800,672 bytes (11,571 count) > 8bk to 16kb: 597,016 bytes (46 count) > 16bk to 32kb: 224,272,704 bytes (10,136 count) > 32bk to 64kb: 64,008 bytes (1 count) > 64bk to 128kb:0 bytes (0 count) > 128kb to 256kb: 0 bytes (0 count) > 256kb to 512kb: 0 bytes (0 count) > 512kb to 1024kb: 0 bytes (0 count) > > 1mb:0 bytes (0 count) > -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.o
Re: [sqlite] Some pieces of the puzzle are coming together
Lacking the status interfaces for 3.6.17 I was forced to mark them as "interface not supported". Simon suggested I track the calls to _malloc, so I've added extensive tracing code. Here is the final output from the two versions: Application: Surveyor.exe Sqlite version: 3.6.17 Date/Time:01/16/2012 16:32:18 Memory Used: interface not supported Page Cache Used: interface not supported Page Cache Overflow: interface not supported Number of Scratch Allocations Used: interface not supported Scratch Overflow: interface not supported Largest Allocation: interface not supported Parser Stack: interface not supported Largest Pcache Allocation:interface not supported Largest Scratch Allocation: interface not supported Number of Outstanding Allocations:interface not supported Lookaside Slots Used: interface not supported Pager Heap Usage: interface not supported Schema Heap Usage:interface not supported Statement Heap/Lookaside Usage: interface not supported Successful lookaside attempts:interface not supported Lookaside failures due to size: interface not supported Lookaside failures due to OOM:interface not supported Page cache hits: interface not supported Page cache misses:interface not supported Cumulative Allocated Memory: 892,318,312 Count of _malloc Calls: 1,072,825 Count of _free Calls: 1,070,971 Cumulative _mallocs by size <= 1kb: 109,025,904 bytes (565,230 count) 1kb to 4kb: 510,357,112 bytes (485,801 count) 4bk to 8kb: 48,005,376 bytes (11,610 count) 8bk to 16kb: 605,208 bytes (47 count) 16bk to 32kb: 224,272,704 bytes (10,136 count) 32bk to 64kb: 52,008 bytes (1 count) 64bk to 128kb:0 bytes (0 count) 128kb to 256kb: 0 bytes (0 count) 256kb to 512kb: 0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb:0 bytes (0 count) Application: Surveyor.exe Sqlite version: 3.7.9 Date/Time:01/16/2012 16:35:01 Memory Used: 7,905,536 (max 8,582,104) bytes Page Cache Used: 0 (max 0) pages Page Cache Overflow: 6,910,576 (max 6,911,600) bytes Number of Scratch Allocations Used: 0 (max 0) Scratch Overflow: 0 (max 24,880) bytes Largest Allocation: 500,042 bytes Parser Stack: 0 Largest Pcache Allocation:4,232 bytes Largest Scratch Allocation: 24,880 bytes Number of Outstanding Allocations:5,835 (max 6,499) Lookaside Slots Used: 500 (max 500) Pager Heap Usage: 6,873,408 bytes Schema Heap Usage:39,560 bytes Statement Heap/Lookaside Usage: 806,592 bytes Successful lookaside attempts:4,888 Lookaside failures due to size: 3,782,307 Lookaside failures due to OOM:4,090,019 Page cache hits: 2,585,425 Page cache misses:0 Cumulative Allocated Memory: 932,315,928 Count of _malloc Calls: 69,859,114 Count of _free Calls: 69,857,292 Cumulative _mallocs by size <= 1kb: 1,118,058,528 bytes (63,640,300 count) 1kb to 4kb: 3,836,490,296 bytes (6,197,060 count) 4bk to 8kb: 47,800,672 bytes (11,571 count) 8bk to 16kb: 597,016 bytes (46 count) 16bk to 32kb: 224,272,704 bytes (10,136 count) 32bk to 64kb: 64,008 bytes (1 count) 64bk to 128kb:0 bytes (0 count) 128kb to 256kb: 0 bytes (0 count) 256kb to 512kb: 0 bytes (0 count) 512kb to 1024kb: 0 bytes (0 count) > 1mb:0 bytes (0 count) ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 5:58 PM, Richard Hipp wrote: > On Fri, Jan 13, 2012 at 4:49 PM, John Elrick >wrote: > > > > > 3.6.17 > > > > Procedure % TimeTimeCalls > > _sqlite3_step 58.4% 1.795,052 > > _memcpy 22.8% 0.691,342,957 > > _memset 7.8% 0.24 465,299 > > ... > > _malloc 1.9% 0.06 95,505 > > > > > > 3.7.9 > > > > Procedure % TimeTimeCalls > > _malloc 56.9% 44.396,975,335 > > _sqlite3_step 30.4% 23.685,052 > > _memcpy 4.8% 3.707,710,259 > > > > Very curious > > SQLite has lots of interfaces that can be used to determine performance and > status information. Some example code from the command-line shell that > accesses this status information is here: > http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 > > I would very much like to see some of these same stats from your > application. Do you think you could add some code like that found in the > shell and give us some more insight into what is going on? > > Richard, per your request: Memory Used : 7,905,536 (max 8,582,104) bytes Page Cache Used : 0 (max 0) pages Page Cache Overflow : 6,910,576 (max 6,911,600) bytes Scratch Used : 0 (max 0) Scratch Overflow : 0 (max 24,880) bytes Malloc Size : 500,042 bytes Parser Stack : 0 Page Cache Size : 4,232 bytes Scratch Size : 24,880 bytes Malloc Count : 5,835 (max 6,499) Lookaside Slots Used : 500 (max 500) Pager Heap Usage : 6,873,408 bytes Schema Heap Usage : 39,560 bytes Statement Heap/Lookaside Usage: 806,592 bytes Successful lookaside attempts : 4,888 Lookaside failures due to size: 3,782,307 Lookaside failures due to OOM : 4,090,019 Page cache hits : 2,585,425 Page cache misses : 0 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 10:33 AM, Richard Hipp wrote: > On Mon, Jan 16, 2012 at 10:29 AM, John Elrick >wrote: > > > > > > > > SQLite has lots of interfaces that can be used to determine performance > > and > > > status information. Some example code from the command-line shell that > > > accesses this status information is here: > > > http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 > > > > > > I would very much like to see some of these same stats from your > > > application. Do you think you could add some code like that found in > the > > > shell and give us some more insight into what is going on? > > > > > > > > Richard, > > > > I created this code and am in the process of gathering preliminary > > statistics. However, I am getting a > > > > SQLITE_MISUSE 21 /* Library used incorrectly */ > > > > when I attempt to use the current _sqlite3_status interface with 3.6.17. > > If you could tell me the interface for that version, I'll add > conditionals > > so we can compare the results of the two. > > > > Some of the SQLITE_DB_STATUS macros have been added after 3.6.17. If you > try to use them on 3.6.17, you'll get a MISUSE error. Really - you ought > to be getting a compile-time error because the symbols don't exist, but I > bet you are using the 3.7.9 header files with the 3.6.17 library. > > You're forgetting I'm using Delphi. I have no access to the .h file. I have to recreate the constants in the Delphi units from the documentation on the site. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 10:29 AM, John Elrick wrote: > > > > SQLite has lots of interfaces that can be used to determine performance > and > > status information. Some example code from the command-line shell that > > accesses this status information is here: > > http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 > > > > I would very much like to see some of these same stats from your > > application. Do you think you could add some code like that found in the > > shell and give us some more insight into what is going on? > > > > > Richard, > > I created this code and am in the process of gathering preliminary > statistics. However, I am getting a > > SQLITE_MISUSE 21 /* Library used incorrectly */ > > when I attempt to use the current _sqlite3_status interface with 3.6.17. > If you could tell me the interface for that version, I'll add conditionals > so we can compare the results of the two. > Some of the SQLITE_DB_STATUS macros have been added after 3.6.17. If you try to use them on 3.6.17, you'll get a MISUSE error. Really - you ought to be getting a compile-time error because the symbols don't exist, but I bet you are using the 3.7.9 header files with the 3.6.17 library. If you can just get us the status information when running 3.7.9 (or 3.7.10 - now available on the website) that will be a big clue by itself. > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 5:58 PM, Richard Hipp wrote: > On Fri, Jan 13, 2012 at 4:49 PM, John Elrick >wrote: > SNIP > SQLite has lots of interfaces that can be used to determine performance and > status information. Some example code from the command-line shell that > accesses this status information is here: > http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 > > I would very much like to see some of these same stats from your > application. Do you think you could add some code like that found in the > shell and give us some more insight into what is going on? > > Richard, I created this code and am in the process of gathering preliminary statistics. However, I am getting a SQLITE_MISUSE 21 /* Library used incorrectly */ when I attempt to use the current _sqlite3_status interface with 3.6.17. If you could tell me the interface for that version, I'll add conditionals so we can compare the results of the two. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 5:37 PM, John Elrick wrote: > > is this test ok for you (still showing bad performance)? > > > > On my side it's about 800 ms for 3.7.9 static and about 6000 memory calls > > during the query. For 3.6.20 the number of calls ~ 7000, the time is > > similar. > > > > > Your test was hard coded. Mine uses bindings. However, I'm not arguing > that something odd is going on. I'm just trying to understand what. > Ok, I did a test with bindings This was query UPDATE RESPONSES SET RESPONSE_NAME = ?, prelisted_value=? WHERE RESPONSE_OID = ? with 5000 rows where both strings were 'abc' and the numbers - random ids (existing) I noticed similar results when the results are system-cached (second and following test in sqlite even after reopening), but when I force resetting system cache (windows cache, not sqlite), the time is about 7-11 seconds. But I think a test db with test data would be more useful for understanding. Can you upload it? Max ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Mon, Jan 16, 2012 at 4:37 AM, Max Vlasov wrote: > On Sun, Jan 15, 2012 at 3:35 AM, John Elrick >wrote: > > > On Fri, Jan 13, 2012 at 5:13 PM, Max Vlasov > wrote: > > > > 5,008 calls to > > > > UPDATE RESPONSES SET > > RESPONSE_NAME = :RESPONSE_NAME, > > prelisted_value = :prelisted_value > > WHERE RESPONSE_OID = :RESPONSE_OID > > > > 3.6.17: 382 ms > > 3.7.9: 5,924 ms > > > > > > John, I did a test reproducing your job with 8 inserts > insert into responses default values > > and making 5000 calls in transaction > > UPDATE RESPONSES SET RESPONSE_NAME = '12345', prelisted_value='12345' > WHERE RESPONSE_OID = abs(random() % 8) > > is this test ok for you (still showing bad performance)? > > On my side it's about 800 ms for 3.7.9 static and about 6000 memory calls > during the query. For 3.6.20 the number of calls ~ 7000, the time is > similar. > > Your test was hard coded. Mine uses bindings. However, I'm not arguing that something odd is going on. I'm just trying to understand what. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Sun, Jan 15, 2012 at 3:35 AM, John Elrick wrote: > On Fri, Jan 13, 2012 at 5:13 PM, Max Vlasov wrote: > > 5,008 calls to > > UPDATE RESPONSES SET > RESPONSE_NAME = :RESPONSE_NAME, > prelisted_value = :prelisted_value > WHERE RESPONSE_OID = :RESPONSE_OID > > 3.6.17: 382 ms > 3.7.9: 5,924 ms > > John, I did a test reproducing your job with 8 inserts insert into responses default values and making 5000 calls in transaction UPDATE RESPONSES SET RESPONSE_NAME = '12345', prelisted_value='12345' WHERE RESPONSE_OID = abs(random() % 8) is this test ok for you (still showing bad performance)? On my side it's about 800 ms for 3.7.9 static and about 6000 memory calls during the query. For 3.6.20 the number of calls ~ 7000, the time is similar. Max ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 5:13 PM, Max Vlasov wrote: > John, > I read your previous post and unfortunately, your conversation with Richard > didn't reveal much details. I worked with scenario similar tou yours > (Delphi + statically linked sqlite) for several years and during this > period an advanced admin/console form was developed that allows dynamical > loading of different versions of sqlite, reporting vfs bandwidth, times and > even the number of memory requests. So consider sharing more information > about your db and queries here or contact me directly if you wish, I hope I > can help at least a little. > > As a quick guess I remember that fts was one of the places that allocated > heavily with some queries, but I can't recall right now. > > There are 88 unique queries run against the database. They are mostly automatically created from a class structure. However, without dumping the entire database in front of you, the following query should provide a good, isolated example: 5,008 calls to UPDATE RESPONSES SET RESPONSE_NAME = :RESPONSE_NAME, prelisted_value = :prelisted_value WHERE RESPONSE_OID = :RESPONSE_OID 3.6.17: 382 ms 3.7.9: 5,924 ms There are 80,021 rows in RESPONSES. The CREATE statement for RESPONSES reads: CREATE TABLE responses ( response_oid integer primary key autoincrement, response_name varchar, definition_parent integer, instance_parent integer, prelisted_value varchar, override_behavior_oid integer, soft_deleted_char varchar default 'F' ); CREATE INDEX response_definition_parent_idx on responses (definition_parent); CREATE UNIQUE INDEX response_instance_parent_idx on responses (instance_parent, definition_parent); CREATE UNIQUE INDEX response_instance_parent_idx2 on responses (response_name, instance_parent, definition_parent); ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Sat, Jan 14, 2012 at 10:42 AM, Dan Kennedy wrote: > On 01/14/2012 04:49 AM, John Elrick wrote: > >> >> So, obviously the problem is that _malloc is being called a much larger >> number of times by 3.7.9 in this particular circumstance -- roughly 70 >> times as often. _memcpy demonstrates roughly 6 times as many calls I >> ran >> a test with a much smaller dataset tracking every call to malloc back to >> the main source line. The results were as follows: >> >> 3.6.17, >> _sqlite3_exec calls _malloc 1,101 times >> _sqlite3_step calls _malloc 1,812 times >> >> 3.7.9 >> _sqlite3_exec calls _malloc 65,227 times >> _sqlite3_step calls _malloc 47,109 times >> >> At this point I've exhausted my avenues of research. Does anyone have any >> further ideas as to what may be going on which could cause this increase >> in >> memory management activity? Or any suggestions of where to look next? >> >> >> > Is there a CREATE INDEX statement in your program? There was a change > a few versions back that caused CREATE INDEX to make a lot more calls > to malloc. > > If you build SQLite with SQLITE_OMIT_MERGE_SORT it bypasses the new > code and builds indexes the old way - with fewer mallocs. There are many CREATE INDEX statements which are all run at the beginning when the database is initially created. I can run a test with your suggestion early next week. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 5:58 PM, Richard Hipp wrote: > On Fri, Jan 13, 2012 at 4:49 PM, John Elrick >wrote: > > > > > 3.6.17 > > > > Procedure % TimeTimeCalls > > _sqlite3_step 58.4% 1.795,052 > > _memcpy 22.8% 0.691,342,957 > > _memset 7.8% 0.24 465,299 > > ... > > _malloc 1.9% 0.06 95,505 > > > > > > 3.7.9 > > > > Procedure % TimeTimeCalls > > _malloc 56.9% 44.396,975,335 > > _sqlite3_step 30.4% 23.685,052 > > _memcpy 4.8% 3.707,710,259 > > > > Very curious > > SQLite has lots of interfaces that can be used to determine performance and > status information. Some example code from the command-line shell that > accesses this status information is here: > http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 > > I would very much like to see some of these same stats from your > application. Do you think you could add some code like that found in the > shell and give us some more insight into what is going on? Thanks for the direction. I'll start working on it on Monday. John ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 5:20 PM, Pavel Ivanov wrote: > > At this point I've exhausted my avenues of research. Does anyone have > any > > further ideas as to what may be going on which could cause this increase > in > > memory management activity? Or any suggestions of where to look next? > > IIRC, SQLite 3.7.9 changed its PCACHE interface and thus page cache > implementation. It introduced one level of indirection into each page > in the cache. But or course I don't think it should result in such > huge amount of additional mallocs. > Also as you see effects only inside Delphi and not in command line > utility it suggests me that Delphi installed its own page cache. And > as it uses old (deprecated in 3.7.9) interface it may have some bad > interaction with new SQLite. > > And just a thought: number of calls to memcpy with 3.7.9 is larger > than with 3.6.17 roughly on the same amount as number of mallocs. > Which suggests that all new calls are actually calls to realloc() (is > number of calls to free() also bigger on 6M?). The number of calls to _free are 6,968,427 in 3.7.9. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 01/14/2012 04:49 AM, John Elrick wrote: So, obviously the problem is that _malloc is being called a much larger number of times by 3.7.9 in this particular circumstance -- roughly 70 times as often. _memcpy demonstrates roughly 6 times as many calls I ran a test with a much smaller dataset tracking every call to malloc back to the main source line. The results were as follows: 3.6.17, _sqlite3_exec calls _malloc 1,101 times _sqlite3_step calls _malloc 1,812 times 3.7.9 _sqlite3_exec calls _malloc 65,227 times _sqlite3_step calls _malloc 47,109 times At this point I've exhausted my avenues of research. Does anyone have any further ideas as to what may be going on which could cause this increase in memory management activity? Or any suggestions of where to look next? Is there a CREATE INDEX statement in your program? There was a change a few versions back that caused CREATE INDEX to make a lot more calls to malloc. If you build SQLite with SQLITE_OMIT_MERGE_SORT it bypasses the new code and builds indexes the old way - with fewer mallocs. Dan. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On Fri, Jan 13, 2012 at 4:49 PM, John Elrick wrote: > > 3.6.17 > > Procedure % TimeTimeCalls > _sqlite3_step 58.4% 1.795,052 > _memcpy 22.8% 0.691,342,957 > _memset 7.8% 0.24 465,299 > ... > _malloc 1.9% 0.06 95,505 > > > 3.7.9 > > Procedure % TimeTimeCalls > _malloc 56.9% 44.396,975,335 > _sqlite3_step 30.4% 23.685,052 > _memcpy 4.8% 3.707,710,259 > Very curious SQLite has lots of interfaces that can be used to determine performance and status information. Some example code from the command-line shell that accesses this status information is here: http://www.sqlite.org/src/artifact/aa4183d4a5243d?ln=990-1076 I would very much like to see some of these same stats from your application. Do you think you could add some code like that found in the shell and give us some more insight into what is going on? -- D. Richard Hipp d...@sqlite.org ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
On 13 Jan 2012, at 9:49pm, John Elrick wrote: > 3.6.17, > _sqlite3_exec calls _malloc 1,101 times > _sqlite3_step calls _malloc 1,812 times > > 3.7.9 > _sqlite3_exec calls _malloc 65,227 times > _sqlite3_step calls _malloc 47,109 times > > At this point I've exhausted my avenues of research. Does anyone have any > further ideas as to what may be going on which could cause this increase in > memory management activity? Or any suggestions of where to look next? Can you patch the call, or do something else, in order to find out the total amount of memory which _malloc is being called to allocate ? In other words, if you have 60 times the number of calls, is it allocating 60 times the amount of memory, or asking for smaller pages so it has to ask for more of them, or are the extra calls to malloc failing ? Simon. ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
> At this point I've exhausted my avenues of research. Does anyone have any > further ideas as to what may be going on which could cause this increase in > memory management activity? Or any suggestions of where to look next? IIRC, SQLite 3.7.9 changed its PCACHE interface and thus page cache implementation. It introduced one level of indirection into each page in the cache. But or course I don't think it should result in such huge amount of additional mallocs. Also as you see effects only inside Delphi and not in command line utility it suggests me that Delphi installed its own page cache. And as it uses old (deprecated in 3.7.9) interface it may have some bad interaction with new SQLite. And just a thought: number of calls to memcpy with 3.7.9 is larger than with 3.6.17 roughly on the same amount as number of mallocs. Which suggests that all new calls are actually calls to realloc() (is number of calls to free() also bigger on 6M?). Pavel On Fri, Jan 13, 2012 at 4:49 PM, John Elrick wrote: > Richard and all, > > On January 6, I wrote a posting (Problems encountered while upgrading > Sqlite from 3.6.7 to 3.7.9) concerning a slow down noticed in upgrading our > Delphi application from using 3.6.17 to 3.7.9. Richard asked for some more > specific information including a replicatable case, which has proven > problematic. Here are the results of my week long investigation. > > I created a logging system which took a specific set of data and converted > all of the automatically run queries to an SQL script which I could use in > a test application. When testing this particular script using a test > program which uses our Delphi wrappers the following times are observed: > > Test Application Run Batch Script > > 3.6.17: 14 seconds > 3.7.9: 10 seconds > > This clearly demonstrates that the newer version of Sqlite is, all things > being equal, superior in performance to the older. However, tests inside > our Delphi application demonstrate that reaching the exact same point of > the database result in the following times: > > Live Application > > 3.6.17: 16 seconds > 3.7.9: 58 seconds > > Extensive profiling of the application finally turned up an unusual and > inexplicable difference between the console application and our regular > application. I am hoping someone on this group may have some ideas. > > I created a Pascal unit whose sole purpose was to delegate to our C > standard library unit. By having delegates in place it becomes easy to > profile the application. This unit is used only by the Sqlite libraries. > > When I execute the application with the same data as above, the following > are the top consumers of time: > > 3.6.17 > > Procedure % Time Time Calls > _sqlite3_step 58.4% 1.79 5,052 > _memcpy 22.8% 0.69 1,342,957 > _memset 7.8% 0.24 465,299 > ... > _malloc 1.9% 0.06 95,505 > > > 3.7.9 > > Procedure % Time Time Calls > _malloc 56.9% 44.39 6,975,335 > _sqlite3_step 30.4% 23.68 5,052 > _memcpy 4.8% 3.70 7,710,259 > > > > So, obviously the problem is that _malloc is being called a much larger > number of times by 3.7.9 in this particular circumstance -- roughly 70 > times as often. _memcpy demonstrates roughly 6 times as many calls I ran > a test with a much smaller dataset tracking every call to malloc back to > the main source line. The results were as follows: > > 3.6.17, > _sqlite3_exec calls _malloc 1,101 times > _sqlite3_step calls _malloc 1,812 times > > 3.7.9 > _sqlite3_exec calls _malloc 65,227 times > _sqlite3_step calls _malloc 47,109 times > > At this point I've exhausted my avenues of research. Does anyone have any > further ideas as to what may be going on which could cause this increase in > memory management activity? Or any suggestions of where to look next? > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
Re: [sqlite] Some pieces of the puzzle are coming together
John, I read your previous post and unfortunately, your conversation with Richard didn't reveal much details. I worked with scenario similar tou yours (Delphi + statically linked sqlite) for several years and during this period an advanced admin/console form was developed that allows dynamical loading of different versions of sqlite, reporting vfs bandwidth, times and even the number of memory requests. So consider sharing more information about your db and queries here or contact me directly if you wish, I hope I can help at least a little. As a quick guess I remember that fts was one of the places that allocated heavily with some queries, but I can't recall right now. Max On Sat, Jan 14, 2012 at 1:49 AM, John Elrick wrote: > Richard and all, > > On January 6, I wrote a posting (Problems encountered while upgrading > Sqlite from 3.6.7 to 3.7.9) concerning a slow down noticed in upgrading our > Delphi application from using 3.6.17 to 3.7.9. Richard asked for some more > specific information including a replicatable case, which has proven > problematic. Here are the results of my week long investigation. > > I created a logging system which took a specific set of data and converted > all of the automatically run queries to an SQL script which I could use in > a test application. When testing this particular script using a test > program which uses our Delphi wrappers the following times are observed: > > Test Application Run Batch Script > > 3.6.17: 14 seconds > 3.7.9: 10 seconds > > This clearly demonstrates that the newer version of Sqlite is, all things > being equal, superior in performance to the older. However, tests inside > our Delphi application demonstrate that reaching the exact same point of > the database result in the following times: > > Live Application > > 3.6.17: 16 seconds > 3.7.9: 58 seconds > > Extensive profiling of the application finally turned up an unusual and > inexplicable difference between the console application and our regular > application. I am hoping someone on this group may have some ideas. > > I created a Pascal unit whose sole purpose was to delegate to our C > standard library unit. By having delegates in place it becomes easy to > profile the application. This unit is used only by the Sqlite libraries. > > When I execute the application with the same data as above, the following > are the top consumers of time: > > 3.6.17 > > Procedure % TimeTimeCalls > _sqlite3_step 58.4% 1.795,052 > _memcpy 22.8% 0.691,342,957 > _memset 7.8% 0.24 465,299 > ... > _malloc 1.9% 0.06 95,505 > > > 3.7.9 > > Procedure % TimeTimeCalls > _malloc 56.9% 44.396,975,335 > _sqlite3_step 30.4% 23.685,052 > _memcpy 4.8% 3.707,710,259 > > > > So, obviously the problem is that _malloc is being called a much larger > number of times by 3.7.9 in this particular circumstance -- roughly 70 > times as often. _memcpy demonstrates roughly 6 times as many calls I ran > a test with a much smaller dataset tracking every call to malloc back to > the main source line. The results were as follows: > > 3.6.17, > _sqlite3_exec calls _malloc 1,101 times > _sqlite3_step calls _malloc 1,812 times > > 3.7.9 > _sqlite3_exec calls _malloc 65,227 times > _sqlite3_step calls _malloc 47,109 times > > At this point I've exhausted my avenues of research. Does anyone have any > further ideas as to what may be going on which could cause this increase in > memory management activity? Or any suggestions of where to look next? > > > -- > John Elrick > Fenestra Technologies > 540-868-1377 > ___ > sqlite-users mailing list > sqlite-users@sqlite.org > http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users > ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users
[sqlite] Some pieces of the puzzle are coming together
Richard and all, On January 6, I wrote a posting (Problems encountered while upgrading Sqlite from 3.6.7 to 3.7.9) concerning a slow down noticed in upgrading our Delphi application from using 3.6.17 to 3.7.9. Richard asked for some more specific information including a replicatable case, which has proven problematic. Here are the results of my week long investigation. I created a logging system which took a specific set of data and converted all of the automatically run queries to an SQL script which I could use in a test application. When testing this particular script using a test program which uses our Delphi wrappers the following times are observed: Test Application Run Batch Script 3.6.17: 14 seconds 3.7.9: 10 seconds This clearly demonstrates that the newer version of Sqlite is, all things being equal, superior in performance to the older. However, tests inside our Delphi application demonstrate that reaching the exact same point of the database result in the following times: Live Application 3.6.17: 16 seconds 3.7.9: 58 seconds Extensive profiling of the application finally turned up an unusual and inexplicable difference between the console application and our regular application. I am hoping someone on this group may have some ideas. I created a Pascal unit whose sole purpose was to delegate to our C standard library unit. By having delegates in place it becomes easy to profile the application. This unit is used only by the Sqlite libraries. When I execute the application with the same data as above, the following are the top consumers of time: 3.6.17 Procedure % TimeTimeCalls _sqlite3_step 58.4% 1.795,052 _memcpy 22.8% 0.691,342,957 _memset 7.8% 0.24 465,299 ... _malloc 1.9% 0.06 95,505 3.7.9 Procedure % TimeTimeCalls _malloc 56.9% 44.396,975,335 _sqlite3_step 30.4% 23.685,052 _memcpy 4.8% 3.707,710,259 So, obviously the problem is that _malloc is being called a much larger number of times by 3.7.9 in this particular circumstance -- roughly 70 times as often. _memcpy demonstrates roughly 6 times as many calls I ran a test with a much smaller dataset tracking every call to malloc back to the main source line. The results were as follows: 3.6.17, _sqlite3_exec calls _malloc 1,101 times _sqlite3_step calls _malloc 1,812 times 3.7.9 _sqlite3_exec calls _malloc 65,227 times _sqlite3_step calls _malloc 47,109 times At this point I've exhausted my avenues of research. Does anyone have any further ideas as to what may be going on which could cause this increase in memory management activity? Or any suggestions of where to look next? -- John Elrick Fenestra Technologies 540-868-1377 ___ sqlite-users mailing list sqlite-users@sqlite.org http://sqlite.org:8080/cgi-bin/mailman/listinfo/sqlite-users