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

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: >

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

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

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

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

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

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

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.

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

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

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

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

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. > > > > > >

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

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

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

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

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,

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

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

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.

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

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

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

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

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.

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

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

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) > >

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) >

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)

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

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

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

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) >

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

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

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

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

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

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.

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

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

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

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

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

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:

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

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

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

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

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

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:

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 > >

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

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: > >

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

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 >

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 > >

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 =

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

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.

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 > >

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

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

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

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.

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

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