Re: [sqlite] Some pieces of the puzzle are coming together

[John Elrick]

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

[Nico Williams]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[John Elrick]

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

[Simon Slavin]

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

[Alek Paunov]

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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[Max Vlasov]

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

[John Elrick]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[Max Vlasov]

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

[John Elrick]

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 

Re: [sqlite] Some pieces of the puzzle are coming together

[John Elrick]

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

[John Elrick]

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: 

Re: [sqlite] Some pieces of the puzzle are coming together

[John Elrick]

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

[Simon Slavin]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[Bill McCormick]

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

[Pavel Ivanov]

> 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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[Max Vlasov]

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

[John Elrick]

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

[John Elrick]

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

[Richard Hipp]

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

[Richard Hipp]

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

[John Elrick]

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

[John Elrick]

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

[Simon Slavin]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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 

Re: [sqlite] Some pieces of the puzzle are coming together

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[Richard Hipp]

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

[John Elrick]

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

[Max Vlasov]

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

[John Elrick]

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

[Max Vlasov]

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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[John Elrick]

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

[Dan Kennedy]

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

[Richard Hipp]

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

[Simon Slavin]

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

[Pavel Ivanov]

> 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

[Max Vlasov]

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