.timer

classic Classic list List threaded Threaded
54 messages Options
123
Reply | Threaded
Open this post in threaded view
|

.timer

curmudgeon
Could someone describe what the return values real, user and sys mean and why there’s sometimes a big difference between real and the sum of user & sys?.

_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Simon Slavin-3
On 14 Jun 2018, at 8:33am, x <[hidden email]> wrote:

> Could someone describe what the return values real, user and sys mean and why there’s sometimes a big difference between real and the sum of user & sys?.

[The following is simplified for clarity.]

'real' -- Elapsed time between the start and end of the command, as measured by the clock on your wall.  Sometimes called 'wall time'.

The other two figures both concern just the process you're interested in, ignoring the many other things the computer is doing at the same time like seeing if you've clicked your mouse, updating your screen, checking to see if your laptop battery is going to run out, etc..

'user' -- Processor time taken by the command itself.  If you look at all the source code for that command, this is the time taken to run that source code.

'sys' -- Processor time taken to execute the system calls the command used.  If the command used system calls to find the current time, allocate memory, and write some bytes to a file, the amount of time each system call took contributes to 'sys', not 'user'.

If 'sys' + 'user' > 'real', something weird happened.

If 'sys' + 'user' < 'real', your computer is busy doing a lot of stuff in the background.  You probably have a printer plugged in, an ethernet or WiFi connection active, a keyboard and mouse pointer being monitored, etc..  This is normal on a modern computer,

Simon.
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

curmudgeon
Thanks for the detail Simon. I’m consistently getting some really big differences where user + sys < real. I’ll post another thread on it but it does seem to be something windows is doing rather than sqlite.



________________________________
From: sqlite-users <[hidden email]> on behalf of Simon Slavin <[hidden email]>
Sent: Thursday, June 14, 2018 9:08:31 AM
To: SQLite mailing list
Subject: Re: [sqlite] .timer

On 14 Jun 2018, at 8:33am, x <[hidden email]> wrote:

> Could someone describe what the return values real, user and sys mean and why there’s sometimes a big difference between real and the sum of user & sys?.

[The following is simplified for clarity.]

'real' -- Elapsed time between the start and end of the command, as measured by the clock on your wall.  Sometimes called 'wall time'.

The other two figures both concern just the process you're interested in, ignoring the many other things the computer is doing at the same time like seeing if you've clicked your mouse, updating your screen, checking to see if your laptop battery is going to run out, etc..

'user' -- Processor time taken by the command itself.  If you look at all the source code for that command, this is the time taken to run that source code.

'sys' -- Processor time taken to execute the system calls the command used.  If the command used system calls to find the current time, allocate memory, and write some bytes to a file, the amount of time each system call took contributes to 'sys', not 'user'.

If 'sys' + 'user' > 'real', something weird happened.

If 'sys' + 'user' < 'real', your computer is busy doing a lot of stuff in the background.  You probably have a printer plugged in, an ethernet or WiFi connection active, a keyboard and mouse pointer being monitored, etc..  This is normal on a modern computer,

Simon.
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Simon Slavin-3
On 14 Jun 2018, at 9:28am, x <[hidden email]> wrote:

> Thanks for the detail Simon. I’m consistently getting some really big differences where user + sys < real. I’ll post another thread on it but it does seem to be something windows is doing rather than sqlite.

You're welcome.  It's barely worth the post here.  SQLite has some control over 'user' and 'sys' but none over 'real'.  If your 'real' got too big, Windows is doing an update, or indexing files, or defragging a hard disk or something.  I've seen a badly-written printer driver which checked ink levels every 5 seconds instead of the intended 5 minutes.  That's the sort of thing that gives you bbd 'real' times.

Simon.
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

R Smith-2
In reply to this post by curmudgeon

On 2018/06/14 10:28 AM, x wrote:
> Thanks for the detail Simon. I’m consistently getting some really big differences where user + sys < real. I’ll post another thread on it but it does seem to be something windows is doing rather than sqlite.

If sys + user << real  -  you are probably running Windows. :)


On a more serious note, if I may - how big are those "big differences"
and on which OS and media and what kind(s) of query?


_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

curmudgeon
It is indeed windows Ryan and at times we’re talking 120 secs versus 30 + 14. This is related to the thread

http://sqlite.1065341.n5.nabble.com/This-is-driving-me-nuts-td102034.html

or at least the latter part of it.



I’m currently working on a repeatable shell demonstration to show how bad a light it shows sqlite in.



________________________________
From: sqlite-users <[hidden email]> on behalf of R Smith <[hidden email]>
Sent: Thursday, June 14, 2018 10:34:58 AM
To: [hidden email]
Subject: Re: [sqlite] .timer


On 2018/06/14 10:28 AM, x wrote:
> Thanks for the detail Simon. I’m consistently getting some really big differences where user + sys < real. I’ll post another thread on it but it does seem to be something windows is doing rather than sqlite.

If sys + user << real  -  you are probably running Windows. :)


On a more serious note, if I may - how big are those "big differences"
and on which OS and media and what kind(s) of query?


_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Dan Kennedy-4
In reply to this post by Simon Slavin-3
On 06/14/2018 03:08 PM, Simon Slavin wrote:

> On 14 Jun 2018, at 8:33am, x <[hidden email]> wrote:
>
>> Could someone describe what the return values real, user and sys mean and why there’s sometimes a big difference between real and the sum of user & sys?.
> [The following is simplified for clarity.]
>
> 'real' -- Elapsed time between the start and end of the command, as measured by the clock on your wall.  Sometimes called 'wall time'.
>
> The other two figures both concern just the process you're interested in, ignoring the many other things the computer is doing at the same time like seeing if you've clicked your mouse, updating your screen, checking to see if your laptop battery is going to run out, etc..
>
> 'user' -- Processor time taken by the command itself.  If you look at all the source code for that command, this is the time taken to run that source code.
>
> 'sys' -- Processor time taken to execute the system calls the command used.  If the command used system calls to find the current time, allocate memory, and write some bytes to a file, the amount of time each system call took contributes to 'sys', not 'user'.
>
> If 'sys' + 'user' > 'real', something weird happened.

Multi-threaded apps often have (sys+user)>real. And you can
build/configure SQLite to use multiple threads when sorting large
amounts of data, so it is possible. Not terribly common though, I would
think.

> If 'sys' + 'user' < 'real', your computer is busy doing a lot of stuff in the background.  You probably have a printer plugged in, an ethernet or WiFi connection active, a keyboard and mouse pointer being monitored, etc..  This is normal on a modern computer,

Another explanation is that your query had to load or sync data from or
to the storage device, not just the OS cache. The "real" time increases
while waiting on IO, but "user" and "sys" do not (since the CPU is idle).

Dan.

_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Keith Medcalf

Exactly.  

REAL is the elapsed time according to the wall clock
USER is the actual time the CPU spent executing user code
SYS  is the actual time the CPU spent executing system code

In "modern" Operating Systems USER usually reflects CPU usage by your process while the CPU is in USER mode (non-protected, or executing at Ring-3 or below), while SYS reflects CPU usage by your process in SUPERVISOR mode (protected, or executing code at Ring-2 or above).

WAIT = REAL - (USER + SYS)

where WAIT is the amount of time that the program was not actually executing (ie, it was waiting for something to happen, whether that waiting occurred in user or system code).  Some I/O devices are co-processsed and interrupt driven or use third-party DMA, these will increase WAIT time.  Some I/O devices use I/O driven by the main CPU, and those devices will increase SYS time, even when they are waiting for something to happen.  Examples of CPU run devices (under Windows) are (almost) anything attached via USB, or non-interrupt driven printers.  Examples of co-processed devices are most (modern) SATA/SCSI type devices (especially if they use NCQ or Data Phase Disconnect).  Older IDE interfaces are usually CPU operated and not interrrupt driven or co-processed.

Some Ring-0 operations that occur in SUPERVISOR mode may be attributed to WAIT (ie, not show up in SYS) even though they are dependant on the CPU to carry them out, examples being "fiddling" with the Memory Mapper Page and Indirection tables (including SMM operations), and context switching, because although they may be triggered by your process, such fiddling cannot usually be attributed to a specific process.  

USER and SYS are the sum of all the CPU used in that mode by each core/thread, so it is possible for SYS+USER to exceed REAL even without explicit multithreading in your code (and even easier if you do have multiple threads).

The ratio between REAL and (USER + SYS) across all the processes running at the same time is called the Multiprogramming Ratio.

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.


>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of Dan Kennedy
>Sent: Thursday, 14 June, 2018 09:13
>To: [hidden email]
>Subject: Re: [sqlite] .timer
>
>On 06/14/2018 03:08 PM, Simon Slavin wrote:
>> On 14 Jun 2018, at 8:33am, x <[hidden email]> wrote:
>>
>>> Could someone describe what the return values real, user and sys
>mean and why there’s sometimes a big difference between real and the
>sum of user & sys?.
>> [The following is simplified for clarity.]
>>
>> 'real' -- Elapsed time between the start and end of the command, as
>measured by the clock on your wall.  Sometimes called 'wall time'.
>>
>> The other two figures both concern just the process you're
>interested in, ignoring the many other things the computer is doing
>at the same time like seeing if you've clicked your mouse, updating
>your screen, checking to see if your laptop battery is going to run
>out, etc..
>>
>> 'user' -- Processor time taken by the command itself.  If you look
>at all the source code for that command, this is the time taken to
>run that source code.
>>
>> 'sys' -- Processor time taken to execute the system calls the
>command used.  If the command used system calls to find the current
>time, allocate memory, and write some bytes to a file, the amount of
>time each system call took contributes to 'sys', not 'user'.
>>
>> If 'sys' + 'user' > 'real', something weird happened.
>
>Multi-threaded apps often have (sys+user)>real. And you can
>build/configure SQLite to use multiple threads when sorting large
>amounts of data, so it is possible. Not terribly common though, I
>would
>think.
>
>> If 'sys' + 'user' < 'real', your computer is busy doing a lot of
>stuff in the background.  You probably have a printer plugged in, an
>ethernet or WiFi connection active, a keyboard and mouse pointer
>being monitored, etc..  This is normal on a modern computer,
>
>Another explanation is that your query had to load or sync data from
>or
>to the storage device, not just the OS cache. The "real" time
>increases
>while waiting on IO, but "user" and "sys" do not (since the CPU is
>idle).
>
>Dan.
>
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Warren Young
In reply to this post by curmudgeon
On Jun 14, 2018, at 8:36 AM, x <[hidden email]> wrote:
>
> It is indeed windows Ryan and at times we’re talking 120 secs versus 30 + 14.

I can think of two good possibilities:

1. Are you using Windows Defender or some other antimalware solution?

If it’s a third-party product, some of those are very aggressive, and they may be poking around in the internals of the SQLite DB on every I/O, which adds tremendous overhead.  That overhead would be charged to another process, not to the system, giving your reported symptom.

2. The other possibility is dodgy hardware, especially the disk holding the SQLite DB, such that the system is getting I/O interrupts with much greater latency than normal, causing it to do work in neither user space nor kernel space, but instead just waiting out wall clock time a lot due to jammed I/O buffers.

So: does the program do the same thing on a different computer?  If you cannot test on another computer, do you get anything interesting in the Windows Event Viewer?
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Bob Friesenhahn
On Thu, 14 Jun 2018, Warren Young wrote:

> On Jun 14, 2018, at 8:36 AM, x <[hidden email]> wrote:
>>
>> It is indeed windows Ryan and at times we’re talking 120 secs versus 30 + 14.
>
> I can think of two good possibilities:
>
> 1. Are you using Windows Defender or some other antimalware solution?
>
> If it’s a third-party product, some of those are very aggressive, and they may be poking around in the internals of the SQLite DB on every I/O, which adds tremendous overhead.  That overhead would be charged to another process, not to the system, giving your reported symptom.

Definitely a +1 on this one.  Beside Windows Defender, Windows 10's
built-in file indexing service will open each new and updated file to
inspect its content, consuming substantial CPU and I/O as well as
blocking access to the content.  These actions are documented to only
occur when it won't impact the user, but of course that is not true.

Something else which can take substantial time which is not attributed
to the program is memory page faults.  These might not be attributed
to the program (e.g. as 'sys' time) since a kernel driver performs the
I/O for page faults.

Bob
--
Bob Friesenhahn
[hidden email], http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Warren Young
On Jun 14, 2018, at 11:00 AM, Bob Friesenhahn <[hidden email]> wrote:

>
> On Thu, 14 Jun 2018, Warren Young wrote:
>
>> On Jun 14, 2018, at 8:36 AM, x <[hidden email]> wrote:
>>>
>>> It is indeed windows Ryan and at times we’re talking 120 secs versus 30 + 14.
>>
>> Are you using Windows Defender or some other antimalware solution?
>
> Definitely a +1 on this one.  Beside Windows Defender, Windows 10's built-in file indexing service…

To clarify, I was putting Windows Defender in a separate class from the more aggressive antimalware packages with that “or”.

While vetting these tests:

    https://www.sqlite.org/fasterthanfs.html

we found that disabling Defender only impacted the native file I/O case.  SQLite was just as fast with Defender enabled because the I/Os were internal to the file, which was kept open throughout the benchmark.  Thus, only one check was presumably made of  the SQLite DB, whereas the comparison against separate files was much slower with Defender enabled, since each of the 100000 test files had to be checked for malware separately.  The numbers reported are with Defender disabled, but only the non-SQLite numbers are greatly affected.

I am simply speculating that there are antimalware products for Windows that will slow SQLite down, unlike Defender.  I couldn’t name one, having not run anything but Defender on my Windows boxes since it first came out.

If your application is closing and re-opening the SQLite DB frequently, then I would expect it to be impacted by Defender.  In the tests linked above, the impact from enabling Defender on the pile-o-files was roughly 10x, but since it’s a synthetic benchmark, your reported ~3x difference might still be due to this.  If so, keep the DB file open!
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

curmudgeon
Thanks for the replies. It is Windows Defender I’m using on a ms surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro. I’ve come up with the following demo using the sqlite shell. In it I use a couple of small apps called AvlRAM and FlushMem. Apart from minor background tasks sqlite3.exe is the only app running.

I downloaded FlushMem from here https://chadaustin.me/flushmem/ and changed it slightly so that it reported the available RAM before and after the flush. I was primarily interested in how sqlite was performing after restarting the computer before any info was lying about in caches as I was encountering some strange timings with such. FlushMem saved me from continually rebooting and yielded results similar to the ones I was experiencing with rebooting.

The code for AvlRAM is as follows

double FreeGBs()
{
        MEMORYSTATUSEX status;
        status.dwLength = sizeof(status);
        GlobalMemoryStatusEx(&status);
        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
}

int _tmain(int argc, _TCHAR* argv[])
{
        std::cout << FreeGBs() << " GBs" << std::endl;
        return 0;
}


Here’s the demo interspersed with comments

SQLite version 3.24.0 2018-06-04 19:24:41
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .timer on
sqlite> .open MyTemp.db -- open empty DB
sqlite> .shell FlushMem
Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs

sqlite> create table test as -- creates test table with 100 million rows
   ...> with recursive cte(x,y) as
   ...> (values(1,'012345678901234567890123456789')
   ...> union all select x+1,y from cte where x<100000000)
   ...> select * from cte;
Run Time: real 77.239 user 68.750000 sys 7.468750
sqlite> .shell AvlRAM
14.1059 GBs

sqlite> create temp table tasc as select RowID from test order by RowID;
Run Time: real 32.473 user 25.203125 sys 7.203125
sqlite> .shell AvlRAM
14.1084 GBs
// little change to RAM, respectable time

sqlite> create temp table tdesc as select RowID from test order by RowID desc;
Run Time: real 32.056 user 24.515625 sys 7.531250
sqlite> .shell FlushMem
Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
// why does the RAM drop 4+ GB due to executing the above?, respectable time


sqlite> create temp table tasc2 as select RowID from test order by RowID;
Run Time: real 38.285 user 26.109375 sys 9.000000
sqlite> .shell FlushMem
Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
// no change to RAM, time a bit more sluggish after ‘reboot’ but still respectable

sqlite> create temp table tdesc2 as select RowID from test order by RowID desc;
Run Time: real 117.765 user 28.265625 sys 13.828125
sqlite> .shell FlushMem
Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
// RAM drops 4+ GB, time is woeful. Why?

// repeat above 2 ‘create temp table’ commands to demonstrate not fluke

sqlite> create temp table tasc3 as select RowID from test order by RowID;
Run Time: real 41.747 user 26.562500 sys 10.625000
sqlite> .shell FlushMem
Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
// no change to RAM, time a bit more sluggish after ‘reboot’ but still respectable

sqlite> create temp table tdesc3 as select RowID from test order by RowID desc;
Run Time: real 118.282 user 29.406250 sys 13.765625
sqlite> .shell FlushMem
Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
// RAM drops 4- GB, time is woeful. Why?

sqlite> .exit



Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a ‘reboot’? I get the impression Windows is caching the pages from the ‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this particular journey I’ve come across tables where the reverse was the case (I.e. it was the ‘asc’ that was woefully slow).

Anyone cast any light on this?
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Keith Medcalf

Cannot reproduce.  

I am using the current trunk that I compile myself with MinGW 8.1.0 on Windows 10 1803 Pro for Workstations.  The laptop has a 4 Ghz Quad Core Xeon and the disk is a Samsung NVMe drive.  About the only relevant change is that I have forced the Windows caching mode from "magical mystery Microsoft mode" to always use "Random access mode".  It is also using the Win32 heap allocator.  I also have 32 GB of RAM and no third or fourth level page indirection or Virtual Arena diddling (that is, swapping is turned off).  I also have SQLite set to a 4K pagesize and have set 262144 pages of cache in SQLite by default.

I forgot how slow CTE's are until I did this ... almost 3 times slower than using generate_series

In RAM only -- Windows caching modes and disk I/O are irrelevant:

>sqlite
SQLite version 3.25.0 2018-06-13 17:19:20
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> create table test as -- creates test table with 100 million rows
   ...> with recursive cte(x,y) as
   ...> (values(1,'012345678901234567890123456789')
   ...>  union all select x+1,y from cte where x<100000000)
   ...> select * from cte;
Run Time: real 34.619 user 34.625000 sys 0.000000
sqlite> drop table test;
Run Time: real 1.578 user 1.578125 sys 0.000000
sqlite> create table test (x integer, y text);
Run Time: real 0.000 user 0.000000 sys 0.000000
sqlite> insert into test select value, '012345678901234567890123456789' from generate_series where start=1 and stop=100000000;
Run Time: real 12.226 user 12.234375 sys 0.000000
sqlite> create temp table tasc1 as select rowid from test order by rowid asc;
Run Time: real 11.408 user 11.140625 sys 0.265625
sqlite> create temp table tdesc1 as select rowid from test order by rowid desc;
Run Time: real 10.251 user 9.875000 sys 0.375000
sqlite> create temp table tdesc2 as select rowid from test order by rowid desc;
Run Time: real 10.188 user 9.828125 sys 0.359375
sqlite> create temp table tasc2 as select rowid from test order by rowid asc;
Run Time: real 11.563 user 11.218750 sys 0.328125
sqlite> ^Z

Timings are all pretty constant ... now with the db on disk ...

>sqlite junk.db
SQLite version 3.25.0 2018-06-13 17:19:20
Enter ".help" for usage hints.
sqlite> create table test (x integer, y text);
Run Time: real 0.015 user 0.000000 sys 0.000000
sqlite> insert into test select value, '012345678901234567890123456789' from generate_series where start=1 and stop=100000000;
Run Time: real 21.206 user 13.234375 sys 6.562500
sqlite> create temp table tasc1 as select rowid from test order by rowid asc;
Run Time: real 13.658 user 10.000000 sys 3.656250
sqlite> create temp table tdesc1 as select rowid from test order by rowid desc;
Run Time: real 12.658 user 9.500000 sys 3.156250
sqlite> create temp table tasc2 as select rowid from test order by rowid asc;
Run Time: real 13.017 user 10.031250 sys 2.984375
sqlite> create temp table tdesc2 as select rowid from test order by rowid desc;
Run Time: real 13.001 user 9.750000 sys 3.250000
sqlite> .exit


2018-06-14 13:47:30 PY2 [D:\]
>dir junk.db
2018-06-14  13:44     4,450,889,728 junk.db
               1 File(s)  4,450,889,728 bytes
               0 Dir(s)  330,480,447,488 bytes free

So we have some difference in SYS time for I/O, but that is about it.  Still constant times.

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.


>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of x
>Sent: Thursday, 14 June, 2018 12:31
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>Thanks for the replies. It is Windows Defender I’m using on a ms
>surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro.
>I’ve come up with the following demo using the sqlite shell. In it I
>use a couple of small apps called AvlRAM and FlushMem. Apart from
>minor background tasks sqlite3.exe is the only app running.
>
>I downloaded FlushMem from here https://chadaustin.me/flushmem/ and
>changed it slightly so that it reported the available RAM before and
>after the flush. I was primarily interested in how sqlite was
>performing after restarting the computer before any info was lying
>about in caches as I was encountering some strange timings with such.
>FlushMem saved me from continually rebooting and yielded results
>similar to the ones I was experiencing with rebooting.
>
>The code for AvlRAM is as follows
>
>double FreeGBs()
>{
>        MEMORYSTATUSEX status;
>        status.dwLength = sizeof(status);
>        GlobalMemoryStatusEx(&status);
>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
>}
>
>int _tmain(int argc, _TCHAR* argv[])
>{
>        std::cout << FreeGBs() << " GBs" << std::endl;
>        return 0;
>}
>
>
>Here’s the demo interspersed with comments
>
>SQLite version 3.24.0 2018-06-04 19:24:41
>Enter ".help" for usage hints.
>Connected to a transient in-memory database.
>Use ".open FILENAME" to reopen on a persistent database.
>sqlite> .timer on
>sqlite> .open MyTemp.db -- open empty DB
>sqlite> .shell FlushMem
>Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs
>
>sqlite> create table test as -- creates test table with 100 million
>rows
>   ...> with recursive cte(x,y) as
>   ...> (values(1,'012345678901234567890123456789')
>   ...> union all select x+1,y from cte where x<100000000)
>   ...> select * from cte;
>Run Time: real 77.239 user 68.750000 sys 7.468750
>sqlite> .shell AvlRAM
>14.1059 GBs
>
>sqlite> create temp table tasc as select RowID from test order by
>RowID;
>Run Time: real 32.473 user 25.203125 sys 7.203125
>sqlite> .shell AvlRAM
>14.1084 GBs
>// little change to RAM, respectable time
>
>sqlite> create temp table tdesc as select RowID from test order by
>RowID desc;
>Run Time: real 32.056 user 24.515625 sys 7.531250
>sqlite> .shell FlushMem
>Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
>// why does the RAM drop 4+ GB due to executing the above?,
>respectable time
>
>
>sqlite> create temp table tasc2 as select RowID from test order by
>RowID;
>Run Time: real 38.285 user 26.109375 sys 9.000000
>sqlite> .shell FlushMem
>Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>still respectable
>
>sqlite> create temp table tdesc2 as select RowID from test order by
>RowID desc;
>Run Time: real 117.765 user 28.265625 sys 13.828125
>sqlite> .shell FlushMem
>Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
>// RAM drops 4+ GB, time is woeful. Why?
>
>// repeat above 2 ‘create temp table’ commands to demonstrate not
>fluke
>
>sqlite> create temp table tasc3 as select RowID from test order by
>RowID;
>Run Time: real 41.747 user 26.562500 sys 10.625000
>sqlite> .shell FlushMem
>Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>still respectable
>
>sqlite> create temp table tdesc3 as select RowID from test order by
>RowID desc;
>Run Time: real 118.282 user 29.406250 sys 13.765625
>sqlite> .shell FlushMem
>Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
>// RAM drops 4- GB, time is woeful. Why?
>
>sqlite> .exit
>
>
>
>Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a
>‘reboot’? I get the impression Windows is caching the pages from the
>‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this
>particular journey I’ve come across tables where the reverse was the
>case (I.e. it was the ‘asc’ that was woefully slow).
>
>Anyone cast any light on this?
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Simon Slavin-3
In reply to this post by curmudgeon
On 14 Jun 2018, at 7:31pm, x <[hidden email]> wrote:

> Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a ‘reboot’? I get the impression Windows is caching the pages from the ‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this particular journey I’ve come across tables where the reverse was the case (I.e. it was the ‘asc’ that was woefully slow).

Windows storage devices traditionally use read-ahead strategy.  This means that if you ask to read sector n they will sometimes read sector n+1 into cache at the same time on the assumption that you will need that next.  This strategy backfires bigtime when applied to solid state drives because unlike spinning rust disks, reading two sectors takes almost twice as long.

Your computer should know this, and shouldn't be trying to apply a read-ahead strategy but something may have gone wrong.

> Anyone cast any light on this?

Now do exactly the same test, but have the file stored on a USB Flash drive instead of the boot volume.  You should be able to do something like

.open d:\MyTemp.db

See how this influences any change.

Simon.
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Keith Medcalf
In reply to this post by Keith Medcalf

See the following web page for how the default "Microsoft Magical Mystery Cache Mode" works on Windows.  The term "Intelligent Read-Ahead" applies only if you are 12 years old (typical Microsoft behaviour).

http://flylib.com/books/en/4.491.1.101/1/

Note that the default mode is completely fracking useless for most intents and purposes, and for databases the SEQUENTIAL mode is bloody awful as well.  

However, the SEQUENTIAL mode seems to match what is being seen (the look ahead is only working in one direction and pages are being unmapped from the system cache at the wrong (read most stoopid) time possible).

So, the changes I made are to function winOpen as follows (after the ticket #2699 comment).  Effectively I always set the flags for RANDOM mode even though I am not Winders Crappy Edition ...

  if( isDelete ){
#if SQLITE_OS_WINCE
    dwFlagsAndAttributes = FILE_ATTRIBUTE_HIDDEN;
    isTemp = 1;
#else
    dwFlagsAndAttributes = FILE_ATTRIBUTE_TEMPORARY
                               | FILE_ATTRIBUTE_HIDDEN
                               | FILE_FLAG_DELETE_ON_CLOSE;
#endif
  }else{
    dwFlagsAndAttributes = FILE_ATTRIBUTE_NORMAL;
  }
  /* Reports from the internet are that performance is always
  ** better if FILE_FLAG_RANDOM_ACCESS is used.  Ticket #2699. */
#if SQLITE_OS_WINCE || SQLITE_WIN32_FILE_RANDOM
  dwFlagsAndAttributes |= FILE_FLAG_RANDOM_ACCESS;
#elif SQLITE_WIN32_FILE_SEQUENTIAL
  dwFlagsAndAttributes |= FILE_FLAG_SEQUENTIAL_SCAN;
#elif SQLITE_WIN32_FILE_WRITETHROUGH
  dwFlagsAndAttributes |= FILE_FLAG_WRITE_THROUGH;
#elif SQLITE_WIN32_FILE_NOBUFFER
  dwFlagsAndAttributes |= FILE_FLAG_NO_BUFFERING;
#endif

This adds the SQLITE_WIN32_FILE_ ... defines and applies them in order to all files opened by the Windows VFS.  I define SQLITE_WIN32_FILE_RANDOM to make sure that the cache mode is always set for RANDOM access and that read-ahead and idiot-mode (ie, Microsoft-style) cache pruning are disabled, thus making the FileSystem cache act in a deterministic LRU page ejecting fashion.

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.


>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of Keith Medcalf
>Sent: Thursday, 14 June, 2018 14:16
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>
>Cannot reproduce.
>
>I am using the current trunk that I compile myself with MinGW 8.1.0
>on Windows 10 1803 Pro for Workstations.  The laptop has a 4 Ghz Quad
>Core Xeon and the disk is a Samsung NVMe drive.  About the only
>relevant change is that I have forced the Windows caching mode from
>"magical mystery Microsoft mode" to always use "Random access mode".
>It is also using the Win32 heap allocator.  I also have 32 GB of RAM
>and no third or fourth level page indirection or Virtual Arena
>diddling (that is, swapping is turned off).  I also have SQLite set
>to a 4K pagesize and have set 262144 pages of cache in SQLite by
>default.
>
>I forgot how slow CTE's are until I did this ... almost 3 times
>slower than using generate_series
>
>In RAM only -- Windows caching modes and disk I/O are irrelevant:
>
>>sqlite
>SQLite version 3.25.0 2018-06-13 17:19:20
>Enter ".help" for usage hints.
>Connected to a transient in-memory database.
>Use ".open FILENAME" to reopen on a persistent database.
>sqlite> create table test as -- creates test table with 100 million
>rows
>   ...> with recursive cte(x,y) as
>   ...> (values(1,'012345678901234567890123456789')
>   ...>  union all select x+1,y from cte where x<100000000)
>   ...> select * from cte;
>Run Time: real 34.619 user 34.625000 sys 0.000000
>sqlite> drop table test;
>Run Time: real 1.578 user 1.578125 sys 0.000000
>sqlite> create table test (x integer, y text);
>Run Time: real 0.000 user 0.000000 sys 0.000000
>sqlite> insert into test select value,
>'012345678901234567890123456789' from generate_series where start=1
>and stop=100000000;
>Run Time: real 12.226 user 12.234375 sys 0.000000
>sqlite> create temp table tasc1 as select rowid from test order by
>rowid asc;
>Run Time: real 11.408 user 11.140625 sys 0.265625
>sqlite> create temp table tdesc1 as select rowid from test order by
>rowid desc;
>Run Time: real 10.251 user 9.875000 sys 0.375000
>sqlite> create temp table tdesc2 as select rowid from test order by
>rowid desc;
>Run Time: real 10.188 user 9.828125 sys 0.359375
>sqlite> create temp table tasc2 as select rowid from test order by
>rowid asc;
>Run Time: real 11.563 user 11.218750 sys 0.328125
>sqlite> ^Z
>
>Timings are all pretty constant ... now with the db on disk ...
>
>>sqlite junk.db
>SQLite version 3.25.0 2018-06-13 17:19:20
>Enter ".help" for usage hints.
>sqlite> create table test (x integer, y text);
>Run Time: real 0.015 user 0.000000 sys 0.000000
>sqlite> insert into test select value,
>'012345678901234567890123456789' from generate_series where start=1
>and stop=100000000;
>Run Time: real 21.206 user 13.234375 sys 6.562500
>sqlite> create temp table tasc1 as select rowid from test order by
>rowid asc;
>Run Time: real 13.658 user 10.000000 sys 3.656250
>sqlite> create temp table tdesc1 as select rowid from test order by
>rowid desc;
>Run Time: real 12.658 user 9.500000 sys 3.156250
>sqlite> create temp table tasc2 as select rowid from test order by
>rowid asc;
>Run Time: real 13.017 user 10.031250 sys 2.984375
>sqlite> create temp table tdesc2 as select rowid from test order by
>rowid desc;
>Run Time: real 13.001 user 9.750000 sys 3.250000
>sqlite> .exit
>
>
>2018-06-14 13:47:30 PY2 [D:\]
>>dir junk.db
>2018-06-14  13:44     4,450,889,728 junk.db
>               1 File(s)  4,450,889,728 bytes
>               0 Dir(s)  330,480,447,488 bytes free
>
>So we have some difference in SYS time for I/O, but that is about it.
>Still constant times.
>
>---
>The fact that there's a Highway to Hell but only a Stairway to Heaven
>says a lot about anticipated traffic volume.
>
>
>>-----Original Message-----
>>From: sqlite-users [mailto:sqlite-users-
>>[hidden email]] On Behalf Of x
>>Sent: Thursday, 14 June, 2018 12:31
>>To: SQLite mailing list
>>Subject: Re: [sqlite] .timer
>>
>>Thanks for the replies. It is Windows Defender I’m using on a ms
>>surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro.
>>I’ve come up with the following demo using the sqlite shell. In it I
>>use a couple of small apps called AvlRAM and FlushMem. Apart from
>>minor background tasks sqlite3.exe is the only app running.
>>
>>I downloaded FlushMem from here https://chadaustin.me/flushmem/ and
>>changed it slightly so that it reported the available RAM before and
>>after the flush. I was primarily interested in how sqlite was
>>performing after restarting the computer before any info was lying
>>about in caches as I was encountering some strange timings with
>such.
>>FlushMem saved me from continually rebooting and yielded results
>>similar to the ones I was experiencing with rebooting.
>>
>>The code for AvlRAM is as follows
>>
>>double FreeGBs()
>>{
>>        MEMORYSTATUSEX status;
>>        status.dwLength = sizeof(status);
>>        GlobalMemoryStatusEx(&status);
>>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
>>}
>>
>>int _tmain(int argc, _TCHAR* argv[])
>>{
>>        std::cout << FreeGBs() << " GBs" << std::endl;
>>        return 0;
>>}
>>
>>
>>Here’s the demo interspersed with comments
>>
>>SQLite version 3.24.0 2018-06-04 19:24:41
>>Enter ".help" for usage hints.
>>Connected to a transient in-memory database.
>>Use ".open FILENAME" to reopen on a persistent database.
>>sqlite> .timer on
>>sqlite> .open MyTemp.db -- open empty DB
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs
>>
>>sqlite> create table test as -- creates test table with 100 million
>>rows
>>   ...> with recursive cte(x,y) as
>>   ...> (values(1,'012345678901234567890123456789')
>>   ...> union all select x+1,y from cte where x<100000000)
>>   ...> select * from cte;
>>Run Time: real 77.239 user 68.750000 sys 7.468750
>>sqlite> .shell AvlRAM
>>14.1059 GBs
>>
>>sqlite> create temp table tasc as select RowID from test order by
>>RowID;
>>Run Time: real 32.473 user 25.203125 sys 7.203125
>>sqlite> .shell AvlRAM
>>14.1084 GBs
>>// little change to RAM, respectable time
>>
>>sqlite> create temp table tdesc as select RowID from test order by
>>RowID desc;
>>Run Time: real 32.056 user 24.515625 sys 7.531250
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
>>// why does the RAM drop 4+ GB due to executing the above?,
>>respectable time
>>
>>
>>sqlite> create temp table tasc2 as select RowID from test order by
>>RowID;
>>Run Time: real 38.285 user 26.109375 sys 9.000000
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>still respectable
>>
>>sqlite> create temp table tdesc2 as select RowID from test order by
>>RowID desc;
>>Run Time: real 117.765 user 28.265625 sys 13.828125
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
>>// RAM drops 4+ GB, time is woeful. Why?
>>
>>// repeat above 2 ‘create temp table’ commands to demonstrate not
>>fluke
>>
>>sqlite> create temp table tasc3 as select RowID from test order by
>>RowID;
>>Run Time: real 41.747 user 26.562500 sys 10.625000
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>still respectable
>>
>>sqlite> create temp table tdesc3 as select RowID from test order by
>>RowID desc;
>>Run Time: real 118.282 user 29.406250 sys 13.765625
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
>>// RAM drops 4- GB, time is woeful. Why?
>>
>>sqlite> .exit
>>
>>
>>
>>Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a
>>‘reboot’? I get the impression Windows is caching the pages from the
>>‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this
>>particular journey I’ve come across tables where the reverse was the
>>case (I.e. it was the ‘asc’ that was woefully slow).
>>
>>Anyone cast any light on this?
>>_______________________________________________
>>sqlite-users mailing list
>>[hidden email]
>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>
>
>
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Simon Slavin-3
In reply to this post by Simon Slavin-3
On 14 Jun 2018, at 10:04pm, Simon Slavin <[hidden email]> wrote:

> Now do exactly the same test, but have the file stored on a USB Flash drive instead of the boot volume.  You should be able to do something like
>
> .open d:\MyTemp.db
>
> See how this influences any change.

Oh, also try the same drive but a different filename which doesn't suggest a database:

.open MyTemp.333

Simon.
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Warren Young
In reply to this post by curmudgeon
On Jun 14, 2018, at 12:31 PM, x <[hidden email]> wrote:
>
> It is Windows Defender I’m using

So does the symptom go away when you turn Defender off?  I would not expect it to, but let’s close the loop on this, okay?

> a ms surface pro 4 with 16 GB ram and 512 GB SSD

I think we can provisionally rule out hardware problems, then.  No spinning rust, and it’s too new to be running into SSD leveling problems.

>        GlobalMemoryStatusEx(&status);
>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);

That’s going to exclude pages taken by the OS page cache, which I believe is important here.

> Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
> // why does the RAM drop 4+ GB due to executing the above?, respectable time

That looks like the Windows page cache to me.  If you write the test DB to disk instead of holding it in memory, it’s 4.1 GiB, just about exactly your delta.  Therefore, I believe Windows is at times caching your whole DB for its own dubious purposes.

Keep in mind that computers are just very fast idiots.  You cannot expect intelligent behavior from them.  They don’t know what you’re trying to accomplish; they can only recite some tricks they’ve been taught by nerds.

By default, SQLite will only cache a smidge under 2 GiB, so it cannot explain your result:

    https://sqlite.org/pragma.html#pragma_cache_size

> sqlite> create temp table tdesc2 as select RowID from test order by RowID desc;
> Run Time: real 117.765 user 28.265625 sys 13.828125
> sqlite> .shell FlushMem
> Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
> // RAM drops 4+ GB, time is woeful. Why?

Try doing the test in reverse: flush the caches, do the descending-order copy, then do the ascending test.  Do the timings flip?

The actual comparison adds only an integer negation operation down in SQLite’s VDBE in DESC mode.  (Currently line 2147 in src/vdbe.c, within the OP_Compare opcode implementation.)  That should cause an immeasurable difference in your test.

One possible explanation is that a reverse sort will cause Windows to read some sequences of memory pages in reverse order, which might play havoc with the CPU’s precaching logic.  

Remember those fast idiots?  One of them is in your CPU, and its job is to try and figure out which RAM lines the programs you are running will want next, so that it can pull them into the L1-3 caches ahead of time, since RAM accesses are about 250x slower than register accesses.  

I highly recommend that you watch this non-trivial presentation:

    https://www.youtube.com/watch?v=4_smHyqgDTU

(“Memory and Caches” by Matt Godbolt, a person you should know if you do not already.)
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

curmudgeon
In reply to this post by Keith Medcalf
Thanks for all the replies and great suggestions. I’m just up but will shortly investigate all.



After reading this post by Clemens Ladisch



http://sqlite.1065341.n5.nabble.com/This-is-driving-me-nuts-tp102034p102105.html



I was guessing the answer might be something along the lines of what is suggested below although I was clueless about how to go about it. To be honest I’m still not sure Keith.



1 Is #2699 an sqlite ticket? I can’t find it.

2 Do I add this code to my sqlite3.c file? If so, whereabouts?

3 Will it still work if I compile in 64 bit mode?



________________________________
From: sqlite-users <[hidden email]> on behalf of Keith Medcalf <[hidden email]>
Sent: Thursday, June 14, 2018 10:09:50 PM
To: SQLite mailing list
Subject: Re: [sqlite] .timer


See the following web page for how the default "Microsoft Magical Mystery Cache Mode" works on Windows.  The term "Intelligent Read-Ahead" applies only if you are 12 years old (typical Microsoft behaviour).

http://flylib.com/books/en/4.491.1.101/1/

Note that the default mode is completely fracking useless for most intents and purposes, and for databases the SEQUENTIAL mode is bloody awful as well.

However, the SEQUENTIAL mode seems to match what is being seen (the look ahead is only working in one direction and pages are being unmapped from the system cache at the wrong (read most stoopid) time possible).

So, the changes I made are to function winOpen as follows (after the ticket #2699 comment).  Effectively I always set the flags for RANDOM mode even though I am not Winders Crappy Edition ...

  if( isDelete ){
#if SQLITE_OS_WINCE
    dwFlagsAndAttributes = FILE_ATTRIBUTE_HIDDEN;
    isTemp = 1;
#else
    dwFlagsAndAttributes = FILE_ATTRIBUTE_TEMPORARY
                               | FILE_ATTRIBUTE_HIDDEN
                               | FILE_FLAG_DELETE_ON_CLOSE;
#endif
  }else{
    dwFlagsAndAttributes = FILE_ATTRIBUTE_NORMAL;
  }
  /* Reports from the internet are that performance is always
  ** better if FILE_FLAG_RANDOM_ACCESS is used.  Ticket #2699. */
#if SQLITE_OS_WINCE || SQLITE_WIN32_FILE_RANDOM
  dwFlagsAndAttributes |= FILE_FLAG_RANDOM_ACCESS;
#elif SQLITE_WIN32_FILE_SEQUENTIAL
  dwFlagsAndAttributes |= FILE_FLAG_SEQUENTIAL_SCAN;
#elif SQLITE_WIN32_FILE_WRITETHROUGH
  dwFlagsAndAttributes |= FILE_FLAG_WRITE_THROUGH;
#elif SQLITE_WIN32_FILE_NOBUFFER
  dwFlagsAndAttributes |= FILE_FLAG_NO_BUFFERING;
#endif

This adds the SQLITE_WIN32_FILE_ ... defines and applies them in order to all files opened by the Windows VFS.  I define SQLITE_WIN32_FILE_RANDOM to make sure that the cache mode is always set for RANDOM access and that read-ahead and idiot-mode (ie, Microsoft-style) cache pruning are disabled, thus making the FileSystem cache act in a deterministic LRU page ejecting fashion.

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.


>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of Keith Medcalf
>Sent: Thursday, 14 June, 2018 14:16
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>
>Cannot reproduce.
>
>I am using the current trunk that I compile myself with MinGW 8.1.0
>on Windows 10 1803 Pro for Workstations.  The laptop has a 4 Ghz Quad
>Core Xeon and the disk is a Samsung NVMe drive.  About the only
>relevant change is that I have forced the Windows caching mode from
>"magical mystery Microsoft mode" to always use "Random access mode".
>It is also using the Win32 heap allocator.  I also have 32 GB of RAM
>and no third or fourth level page indirection or Virtual Arena
>diddling (that is, swapping is turned off).  I also have SQLite set
>to a 4K pagesize and have set 262144 pages of cache in SQLite by
>default.
>
>I forgot how slow CTE's are until I did this ... almost 3 times
>slower than using generate_series
>
>In RAM only -- Windows caching modes and disk I/O are irrelevant:
>
>>sqlite
>SQLite version 3.25.0 2018-06-13 17:19:20
>Enter ".help" for usage hints.
>Connected to a transient in-memory database.
>Use ".open FILENAME" to reopen on a persistent database.
>sqlite> create table test as -- creates test table with 100 million
>rows
>   ...> with recursive cte(x,y) as
>   ...> (values(1,'012345678901234567890123456789')
>   ...>  union all select x+1,y from cte where x<100000000)
>   ...> select * from cte;
>Run Time: real 34.619 user 34.625000 sys 0.000000
>sqlite> drop table test;
>Run Time: real 1.578 user 1.578125 sys 0.000000
>sqlite> create table test (x integer, y text);
>Run Time: real 0.000 user 0.000000 sys 0.000000
>sqlite> insert into test select value,
>'012345678901234567890123456789' from generate_series where start=1
>and stop=100000000;
>Run Time: real 12.226 user 12.234375 sys 0.000000
>sqlite> create temp table tasc1 as select rowid from test order by
>rowid asc;
>Run Time: real 11.408 user 11.140625 sys 0.265625
>sqlite> create temp table tdesc1 as select rowid from test order by
>rowid desc;
>Run Time: real 10.251 user 9.875000 sys 0.375000
>sqlite> create temp table tdesc2 as select rowid from test order by
>rowid desc;
>Run Time: real 10.188 user 9.828125 sys 0.359375
>sqlite> create temp table tasc2 as select rowid from test order by
>rowid asc;
>Run Time: real 11.563 user 11.218750 sys 0.328125
>sqlite> ^Z
>
>Timings are all pretty constant ... now with the db on disk ...
>
>>sqlite junk.db
>SQLite version 3.25.0 2018-06-13 17:19:20
>Enter ".help" for usage hints.
>sqlite> create table test (x integer, y text);
>Run Time: real 0.015 user 0.000000 sys 0.000000
>sqlite> insert into test select value,
>'012345678901234567890123456789' from generate_series where start=1
>and stop=100000000;
>Run Time: real 21.206 user 13.234375 sys 6.562500
>sqlite> create temp table tasc1 as select rowid from test order by
>rowid asc;
>Run Time: real 13.658 user 10.000000 sys 3.656250
>sqlite> create temp table tdesc1 as select rowid from test order by
>rowid desc;
>Run Time: real 12.658 user 9.500000 sys 3.156250
>sqlite> create temp table tasc2 as select rowid from test order by
>rowid asc;
>Run Time: real 13.017 user 10.031250 sys 2.984375
>sqlite> create temp table tdesc2 as select rowid from test order by
>rowid desc;
>Run Time: real 13.001 user 9.750000 sys 3.250000
>sqlite> .exit
>
>
>2018-06-14 13:47:30 PY2 [D:\]
>>dir junk.db
>2018-06-14  13:44     4,450,889,728 junk.db
>               1 File(s)  4,450,889,728 bytes
>               0 Dir(s)  330,480,447,488 bytes free
>
>So we have some difference in SYS time for I/O, but that is about it.
>Still constant times.
>
>---
>The fact that there's a Highway to Hell but only a Stairway to Heaven
>says a lot about anticipated traffic volume.
>
>
>>-----Original Message-----
>>From: sqlite-users [mailto:sqlite-users-
>>[hidden email]] On Behalf Of x
>>Sent: Thursday, 14 June, 2018 12:31
>>To: SQLite mailing list
>>Subject: Re: [sqlite] .timer
>>
>>Thanks for the replies. It is Windows Defender I’m using on a ms
>>surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro.
>>I’ve come up with the following demo using the sqlite shell. In it I
>>use a couple of small apps called AvlRAM and FlushMem. Apart from
>>minor background tasks sqlite3.exe is the only app running.
>>
>>I downloaded FlushMem from here https://chadaustin.me/flushmem/ and
>>changed it slightly so that it reported the available RAM before and
>>after the flush. I was primarily interested in how sqlite was
>>performing after restarting the computer before any info was lying
>>about in caches as I was encountering some strange timings with
>such.
>>FlushMem saved me from continually rebooting and yielded results
>>similar to the ones I was experiencing with rebooting.
>>
>>The code for AvlRAM is as follows
>>
>>double FreeGBs()
>>{
>>        MEMORYSTATUSEX status;
>>        status.dwLength = sizeof(status);
>>        GlobalMemoryStatusEx(&status);
>>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
>>}
>>
>>int _tmain(int argc, _TCHAR* argv[])
>>{
>>        std::cout << FreeGBs() << " GBs" << std::endl;
>>        return 0;
>>}
>>
>>
>>Here’s the demo interspersed with comments
>>
>>SQLite version 3.24.0 2018-06-04 19:24:41
>>Enter ".help" for usage hints.
>>Connected to a transient in-memory database.
>>Use ".open FILENAME" to reopen on a persistent database.
>>sqlite> .timer on
>>sqlite> .open MyTemp.db -- open empty DB
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs
>>
>>sqlite> create table test as -- creates test table with 100 million
>>rows
>>   ...> with recursive cte(x,y) as
>>   ...> (values(1,'012345678901234567890123456789')
>>   ...> union all select x+1,y from cte where x<100000000)
>>   ...> select * from cte;
>>Run Time: real 77.239 user 68.750000 sys 7.468750
>>sqlite> .shell AvlRAM
>>14.1059 GBs
>>
>>sqlite> create temp table tasc as select RowID from test order by
>>RowID;
>>Run Time: real 32.473 user 25.203125 sys 7.203125
>>sqlite> .shell AvlRAM
>>14.1084 GBs
>>// little change to RAM, respectable time
>>
>>sqlite> create temp table tdesc as select RowID from test order by
>>RowID desc;
>>Run Time: real 32.056 user 24.515625 sys 7.531250
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
>>// why does the RAM drop 4+ GB due to executing the above?,
>>respectable time
>>
>>
>>sqlite> create temp table tasc2 as select RowID from test order by
>>RowID;
>>Run Time: real 38.285 user 26.109375 sys 9.000000
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>still respectable
>>
>>sqlite> create temp table tdesc2 as select RowID from test order by
>>RowID desc;
>>Run Time: real 117.765 user 28.265625 sys 13.828125
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
>>// RAM drops 4+ GB, time is woeful. Why?
>>
>>// repeat above 2 ‘create temp table’ commands to demonstrate not
>>fluke
>>
>>sqlite> create temp table tasc3 as select RowID from test order by
>>RowID;
>>Run Time: real 41.747 user 26.562500 sys 10.625000
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>still respectable
>>
>>sqlite> create temp table tdesc3 as select RowID from test order by
>>RowID desc;
>>Run Time: real 118.282 user 29.406250 sys 13.765625
>>sqlite> .shell FlushMem
>>Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
>>// RAM drops 4- GB, time is woeful. Why?
>>
>>sqlite> .exit
>>
>>
>>
>>Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a
>>‘reboot’? I get the impression Windows is caching the pages from the
>>‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this
>>particular journey I’ve come across tables where the reverse was the
>>case (I.e. it was the ‘asc’ that was woefully slow).
>>
>>Anyone cast any light on this?
>>_______________________________________________
>>sqlite-users mailing list
>>[hidden email]
>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>
>
>
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Keith Medcalf

Yes.  Search your sqlite3.c for #2966 (there is only one instance and it is in the winOpen function, somewhere around line 44847).  The code that is there will be an #ifdef that forces RANDOM_ACCESS only for WINCE.  Just change it so that you can compile it with RANDOM_ACCESS set and see if that makes a difference.  And yes, it will work in both 32 and 64 bit on Windows ... It will at least make the Windows caching deterministic (technically LRU).

I know that Windows supposedly has some builtin rules about how it sets the default cache mode, but you should really have the whole file in the cache after each command since that is the purpose of the cache (memory not used is money wasted).

Then re-run your test without freeing up physical cache memory between the runs (so the database stays in the cache).  The first run though the file will take a long time (SYS I/O Time) but subsequent passes should be very fast since the data is all already in the cache ... (the USER time should stay about the same, but the SYS time will change depending on whether the file is in the cache or not).

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.

>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of x
>Sent: Friday, 15 June, 2018 00:50
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>Thanks for all the replies and great suggestions. I’m just up but
>will shortly investigate all.
>
>
>
>After reading this post by Clemens Ladisch
>
>
>
>http://sqlite.1065341.n5.nabble.com/This-is-driving-me-nuts-
>tp102034p102105.html
>
>
>
>I was guessing the answer might be something along the lines of what
>is suggested below although I was clueless about how to go about it.
>To be honest I’m still not sure Keith.
>
>
>
>1 Is #2699 an sqlite ticket? I can’t find it.
>
>2 Do I add this code to my sqlite3.c file? If so, whereabouts?
>
>3 Will it still work if I compile in 64 bit mode?
>
>
>
>________________________________
>From: sqlite-users <[hidden email]> on
>behalf of Keith Medcalf <[hidden email]>
>Sent: Thursday, June 14, 2018 10:09:50 PM
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>
>See the following web page for how the default "Microsoft Magical
>Mystery Cache Mode" works on Windows.  The term "Intelligent Read-
>Ahead" applies only if you are 12 years old (typical Microsoft
>behaviour).
>
>http://flylib.com/books/en/4.491.1.101/1/
>
>Note that the default mode is completely fracking useless for most
>intents and purposes, and for databases the SEQUENTIAL mode is bloody
>awful as well.
>
>However, the SEQUENTIAL mode seems to match what is being seen (the
>look ahead is only working in one direction and pages are being
>unmapped from the system cache at the wrong (read most stoopid) time
>possible).
>
>So, the changes I made are to function winOpen as follows (after the
>ticket #2699 comment).  Effectively I always set the flags for RANDOM
>mode even though I am not Winders Crappy Edition ...
>
>  if( isDelete ){
>#if SQLITE_OS_WINCE
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_HIDDEN;
>    isTemp = 1;
>#else
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_TEMPORARY
>                               | FILE_ATTRIBUTE_HIDDEN
>                               | FILE_FLAG_DELETE_ON_CLOSE;
>#endif
>  }else{
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_NORMAL;
>  }
>  /* Reports from the internet are that performance is always
>  ** better if FILE_FLAG_RANDOM_ACCESS is used.  Ticket #2699. */
>#if SQLITE_OS_WINCE || SQLITE_WIN32_FILE_RANDOM
>  dwFlagsAndAttributes |= FILE_FLAG_RANDOM_ACCESS;
>#elif SQLITE_WIN32_FILE_SEQUENTIAL
>  dwFlagsAndAttributes |= FILE_FLAG_SEQUENTIAL_SCAN;
>#elif SQLITE_WIN32_FILE_WRITETHROUGH
>  dwFlagsAndAttributes |= FILE_FLAG_WRITE_THROUGH;
>#elif SQLITE_WIN32_FILE_NOBUFFER
>  dwFlagsAndAttributes |= FILE_FLAG_NO_BUFFERING;
>#endif
>
>This adds the SQLITE_WIN32_FILE_ ... defines and applies them in
>order to all files opened by the Windows VFS.  I define
>SQLITE_WIN32_FILE_RANDOM to make sure that the cache mode is always
>set for RANDOM access and that read-ahead and idiot-mode (ie,
>Microsoft-style) cache pruning are disabled, thus making the
>FileSystem cache act in a deterministic LRU page ejecting fashion.
>
>---
>The fact that there's a Highway to Hell but only a Stairway to Heaven
>says a lot about anticipated traffic volume.
>
>
>>-----Original Message-----
>>From: sqlite-users [mailto:sqlite-users-
>>[hidden email]] On Behalf Of Keith Medcalf
>>Sent: Thursday, 14 June, 2018 14:16
>>To: SQLite mailing list
>>Subject: Re: [sqlite] .timer
>>
>>
>>Cannot reproduce.
>>
>>I am using the current trunk that I compile myself with MinGW 8.1.0
>>on Windows 10 1803 Pro for Workstations.  The laptop has a 4 Ghz
>Quad
>>Core Xeon and the disk is a Samsung NVMe drive.  About the only
>>relevant change is that I have forced the Windows caching mode from
>>"magical mystery Microsoft mode" to always use "Random access mode".
>>It is also using the Win32 heap allocator.  I also have 32 GB of RAM
>>and no third or fourth level page indirection or Virtual Arena
>>diddling (that is, swapping is turned off).  I also have SQLite set
>>to a 4K pagesize and have set 262144 pages of cache in SQLite by
>>default.
>>
>>I forgot how slow CTE's are until I did this ... almost 3 times
>>slower than using generate_series
>>
>>In RAM only -- Windows caching modes and disk I/O are irrelevant:
>>
>>>sqlite
>>SQLite version 3.25.0 2018-06-13 17:19:20
>>Enter ".help" for usage hints.
>>Connected to a transient in-memory database.
>>Use ".open FILENAME" to reopen on a persistent database.
>>sqlite> create table test as -- creates test table with 100 million
>>rows
>>   ...> with recursive cte(x,y) as
>>   ...> (values(1,'012345678901234567890123456789')
>>   ...>  union all select x+1,y from cte where x<100000000)
>>   ...> select * from cte;
>>Run Time: real 34.619 user 34.625000 sys 0.000000
>>sqlite> drop table test;
>>Run Time: real 1.578 user 1.578125 sys 0.000000
>>sqlite> create table test (x integer, y text);
>>Run Time: real 0.000 user 0.000000 sys 0.000000
>>sqlite> insert into test select value,
>>'012345678901234567890123456789' from generate_series where start=1
>>and stop=100000000;
>>Run Time: real 12.226 user 12.234375 sys 0.000000
>>sqlite> create temp table tasc1 as select rowid from test order by
>>rowid asc;
>>Run Time: real 11.408 user 11.140625 sys 0.265625
>>sqlite> create temp table tdesc1 as select rowid from test order by
>>rowid desc;
>>Run Time: real 10.251 user 9.875000 sys 0.375000
>>sqlite> create temp table tdesc2 as select rowid from test order by
>>rowid desc;
>>Run Time: real 10.188 user 9.828125 sys 0.359375
>>sqlite> create temp table tasc2 as select rowid from test order by
>>rowid asc;
>>Run Time: real 11.563 user 11.218750 sys 0.328125
>>sqlite> ^Z
>>
>>Timings are all pretty constant ... now with the db on disk ...
>>
>>>sqlite junk.db
>>SQLite version 3.25.0 2018-06-13 17:19:20
>>Enter ".help" for usage hints.
>>sqlite> create table test (x integer, y text);
>>Run Time: real 0.015 user 0.000000 sys 0.000000
>>sqlite> insert into test select value,
>>'012345678901234567890123456789' from generate_series where start=1
>>and stop=100000000;
>>Run Time: real 21.206 user 13.234375 sys 6.562500
>>sqlite> create temp table tasc1 as select rowid from test order by
>>rowid asc;
>>Run Time: real 13.658 user 10.000000 sys 3.656250
>>sqlite> create temp table tdesc1 as select rowid from test order by
>>rowid desc;
>>Run Time: real 12.658 user 9.500000 sys 3.156250
>>sqlite> create temp table tasc2 as select rowid from test order by
>>rowid asc;
>>Run Time: real 13.017 user 10.031250 sys 2.984375
>>sqlite> create temp table tdesc2 as select rowid from test order by
>>rowid desc;
>>Run Time: real 13.001 user 9.750000 sys 3.250000
>>sqlite> .exit
>>
>>
>>2018-06-14 13:47:30 PY2 [D:\]
>>>dir junk.db
>>2018-06-14  13:44     4,450,889,728 junk.db
>>               1 File(s)  4,450,889,728 bytes
>>               0 Dir(s)  330,480,447,488 bytes free
>>
>>So we have some difference in SYS time for I/O, but that is about
>it.
>>Still constant times.
>>
>>---
>>The fact that there's a Highway to Hell but only a Stairway to
>Heaven
>>says a lot about anticipated traffic volume.
>>
>>
>>>-----Original Message-----
>>>From: sqlite-users [mailto:sqlite-users-
>>>[hidden email]] On Behalf Of x
>>>Sent: Thursday, 14 June, 2018 12:31
>>>To: SQLite mailing list
>>>Subject: Re: [sqlite] .timer
>>>
>>>Thanks for the replies. It is Windows Defender I’m using on a ms
>>>surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro.
>>>I’ve come up with the following demo using the sqlite shell. In it
>I
>>>use a couple of small apps called AvlRAM and FlushMem. Apart from
>>>minor background tasks sqlite3.exe is the only app running.
>>>
>>>I downloaded FlushMem from here https://chadaustin.me/flushmem/ and
>>>changed it slightly so that it reported the available RAM before
>and
>>>after the flush. I was primarily interested in how sqlite was
>>>performing after restarting the computer before any info was lying
>>>about in caches as I was encountering some strange timings with
>>such.
>>>FlushMem saved me from continually rebooting and yielded results
>>>similar to the ones I was experiencing with rebooting.
>>>
>>>The code for AvlRAM is as follows
>>>
>>>double FreeGBs()
>>>{
>>>        MEMORYSTATUSEX status;
>>>        status.dwLength = sizeof(status);
>>>        GlobalMemoryStatusEx(&status);
>>>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
>>>}
>>>
>>>int _tmain(int argc, _TCHAR* argv[])
>>>{
>>>        std::cout << FreeGBs() << " GBs" << std::endl;
>>>        return 0;
>>>}
>>>
>>>
>>>Here’s the demo interspersed with comments
>>>
>>>SQLite version 3.24.0 2018-06-04 19:24:41
>>>Enter ".help" for usage hints.
>>>Connected to a transient in-memory database.
>>>Use ".open FILENAME" to reopen on a persistent database.
>>>sqlite> .timer on
>>>sqlite> .open MyTemp.db -- open empty DB
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs
>>>
>>>sqlite> create table test as -- creates test table with 100 million
>>>rows
>>>   ...> with recursive cte(x,y) as
>>>   ...> (values(1,'012345678901234567890123456789')
>>>   ...> union all select x+1,y from cte where x<100000000)
>>>   ...> select * from cte;
>>>Run Time: real 77.239 user 68.750000 sys 7.468750
>>>sqlite> .shell AvlRAM
>>>14.1059 GBs
>>>
>>>sqlite> create temp table tasc as select RowID from test order by
>>>RowID;
>>>Run Time: real 32.473 user 25.203125 sys 7.203125
>>>sqlite> .shell AvlRAM
>>>14.1084 GBs
>>>// little change to RAM, respectable time
>>>
>>>sqlite> create temp table tdesc as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 32.056 user 24.515625 sys 7.531250
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
>>>// why does the RAM drop 4+ GB due to executing the above?,
>>>respectable time
>>>
>>>
>>>sqlite> create temp table tasc2 as select RowID from test order by
>>>RowID;
>>>Run Time: real 38.285 user 26.109375 sys 9.000000
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
>>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>>still respectable
>>>
>>>sqlite> create temp table tdesc2 as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 117.765 user 28.265625 sys 13.828125
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
>>>// RAM drops 4+ GB, time is woeful. Why?
>>>
>>>// repeat above 2 ‘create temp table’ commands to demonstrate not
>>>fluke
>>>
>>>sqlite> create temp table tasc3 as select RowID from test order by
>>>RowID;
>>>Run Time: real 41.747 user 26.562500 sys 10.625000
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
>>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>>still respectable
>>>
>>>sqlite> create temp table tdesc3 as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 118.282 user 29.406250 sys 13.765625
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
>>>// RAM drops 4- GB, time is woeful. Why?
>>>
>>>sqlite> .exit
>>>
>>>
>>>
>>>Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a
>>>‘reboot’? I get the impression Windows is caching the pages from
>the
>>>‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this
>>>particular journey I’ve come across tables where the reverse was
>the
>>>case (I.e. it was the ‘asc’ that was woefully slow).
>>>
>>>Anyone cast any light on this?
>>>_______________________________________________
>>>sqlite-users mailing list
>>>[hidden email]
>>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-
>users
>>
>>
>>
>>_______________________________________________
>>sqlite-users mailing list
>>[hidden email]
>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>
>
>
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
Reply | Threaded
Open this post in threaded view
|

Re: .timer

Keith Medcalf
In reply to this post by curmudgeon

Actually I cannot reproduce even if I turn off forced RANDOM mode for the cache, reduce the size of the sqlite3 cache to the default, and make sure the temp_store is on disk (not my default).

I do note, however, that the actual CPU used is relatively constant (USER+SYS) and that it is the REAL time only that is going "bonkers" which suggests some process other than sqlite is what is causing the slowdown.  It could be something the hardware is doing -- I have never used a "tablet" as if it were a computer ...

---
The fact that there's a Highway to Hell but only a Stairway to Heaven says a lot about anticipated traffic volume.


>-----Original Message-----
>From: sqlite-users [mailto:sqlite-users-
>[hidden email]] On Behalf Of x
>Sent: Friday, 15 June, 2018 00:50
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>Thanks for all the replies and great suggestions. I’m just up but
>will shortly investigate all.
>
>
>
>After reading this post by Clemens Ladisch
>
>
>
>http://sqlite.1065341.n5.nabble.com/This-is-driving-me-nuts-
>tp102034p102105.html
>
>
>
>I was guessing the answer might be something along the lines of what
>is suggested below although I was clueless about how to go about it.
>To be honest I’m still not sure Keith.
>
>
>
>1 Is #2699 an sqlite ticket? I can’t find it.
>
>2 Do I add this code to my sqlite3.c file? If so, whereabouts?
>
>3 Will it still work if I compile in 64 bit mode?
>
>
>
>________________________________
>From: sqlite-users <[hidden email]> on
>behalf of Keith Medcalf <[hidden email]>
>Sent: Thursday, June 14, 2018 10:09:50 PM
>To: SQLite mailing list
>Subject: Re: [sqlite] .timer
>
>
>See the following web page for how the default "Microsoft Magical
>Mystery Cache Mode" works on Windows.  The term "Intelligent Read-
>Ahead" applies only if you are 12 years old (typical Microsoft
>behaviour).
>
>http://flylib.com/books/en/4.491.1.101/1/
>
>Note that the default mode is completely fracking useless for most
>intents and purposes, and for databases the SEQUENTIAL mode is bloody
>awful as well.
>
>However, the SEQUENTIAL mode seems to match what is being seen (the
>look ahead is only working in one direction and pages are being
>unmapped from the system cache at the wrong (read most stoopid) time
>possible).
>
>So, the changes I made are to function winOpen as follows (after the
>ticket #2699 comment).  Effectively I always set the flags for RANDOM
>mode even though I am not Winders Crappy Edition ...
>
>  if( isDelete ){
>#if SQLITE_OS_WINCE
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_HIDDEN;
>    isTemp = 1;
>#else
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_TEMPORARY
>                               | FILE_ATTRIBUTE_HIDDEN
>                               | FILE_FLAG_DELETE_ON_CLOSE;
>#endif
>  }else{
>    dwFlagsAndAttributes = FILE_ATTRIBUTE_NORMAL;
>  }
>  /* Reports from the internet are that performance is always
>  ** better if FILE_FLAG_RANDOM_ACCESS is used.  Ticket #2699. */
>#if SQLITE_OS_WINCE || SQLITE_WIN32_FILE_RANDOM
>  dwFlagsAndAttributes |= FILE_FLAG_RANDOM_ACCESS;
>#elif SQLITE_WIN32_FILE_SEQUENTIAL
>  dwFlagsAndAttributes |= FILE_FLAG_SEQUENTIAL_SCAN;
>#elif SQLITE_WIN32_FILE_WRITETHROUGH
>  dwFlagsAndAttributes |= FILE_FLAG_WRITE_THROUGH;
>#elif SQLITE_WIN32_FILE_NOBUFFER
>  dwFlagsAndAttributes |= FILE_FLAG_NO_BUFFERING;
>#endif
>
>This adds the SQLITE_WIN32_FILE_ ... defines and applies them in
>order to all files opened by the Windows VFS.  I define
>SQLITE_WIN32_FILE_RANDOM to make sure that the cache mode is always
>set for RANDOM access and that read-ahead and idiot-mode (ie,
>Microsoft-style) cache pruning are disabled, thus making the
>FileSystem cache act in a deterministic LRU page ejecting fashion.
>
>---
>The fact that there's a Highway to Hell but only a Stairway to Heaven
>says a lot about anticipated traffic volume.
>
>
>>-----Original Message-----
>>From: sqlite-users [mailto:sqlite-users-
>>[hidden email]] On Behalf Of Keith Medcalf
>>Sent: Thursday, 14 June, 2018 14:16
>>To: SQLite mailing list
>>Subject: Re: [sqlite] .timer
>>
>>
>>Cannot reproduce.
>>
>>I am using the current trunk that I compile myself with MinGW 8.1.0
>>on Windows 10 1803 Pro for Workstations.  The laptop has a 4 Ghz
>Quad
>>Core Xeon and the disk is a Samsung NVMe drive.  About the only
>>relevant change is that I have forced the Windows caching mode from
>>"magical mystery Microsoft mode" to always use "Random access mode".
>>It is also using the Win32 heap allocator.  I also have 32 GB of RAM
>>and no third or fourth level page indirection or Virtual Arena
>>diddling (that is, swapping is turned off).  I also have SQLite set
>>to a 4K pagesize and have set 262144 pages of cache in SQLite by
>>default.
>>
>>I forgot how slow CTE's are until I did this ... almost 3 times
>>slower than using generate_series
>>
>>In RAM only -- Windows caching modes and disk I/O are irrelevant:
>>
>>>sqlite
>>SQLite version 3.25.0 2018-06-13 17:19:20
>>Enter ".help" for usage hints.
>>Connected to a transient in-memory database.
>>Use ".open FILENAME" to reopen on a persistent database.
>>sqlite> create table test as -- creates test table with 100 million
>>rows
>>   ...> with recursive cte(x,y) as
>>   ...> (values(1,'012345678901234567890123456789')
>>   ...>  union all select x+1,y from cte where x<100000000)
>>   ...> select * from cte;
>>Run Time: real 34.619 user 34.625000 sys 0.000000
>>sqlite> drop table test;
>>Run Time: real 1.578 user 1.578125 sys 0.000000
>>sqlite> create table test (x integer, y text);
>>Run Time: real 0.000 user 0.000000 sys 0.000000
>>sqlite> insert into test select value,
>>'012345678901234567890123456789' from generate_series where start=1
>>and stop=100000000;
>>Run Time: real 12.226 user 12.234375 sys 0.000000
>>sqlite> create temp table tasc1 as select rowid from test order by
>>rowid asc;
>>Run Time: real 11.408 user 11.140625 sys 0.265625
>>sqlite> create temp table tdesc1 as select rowid from test order by
>>rowid desc;
>>Run Time: real 10.251 user 9.875000 sys 0.375000
>>sqlite> create temp table tdesc2 as select rowid from test order by
>>rowid desc;
>>Run Time: real 10.188 user 9.828125 sys 0.359375
>>sqlite> create temp table tasc2 as select rowid from test order by
>>rowid asc;
>>Run Time: real 11.563 user 11.218750 sys 0.328125
>>sqlite> ^Z
>>
>>Timings are all pretty constant ... now with the db on disk ...
>>
>>>sqlite junk.db
>>SQLite version 3.25.0 2018-06-13 17:19:20
>>Enter ".help" for usage hints.
>>sqlite> create table test (x integer, y text);
>>Run Time: real 0.015 user 0.000000 sys 0.000000
>>sqlite> insert into test select value,
>>'012345678901234567890123456789' from generate_series where start=1
>>and stop=100000000;
>>Run Time: real 21.206 user 13.234375 sys 6.562500
>>sqlite> create temp table tasc1 as select rowid from test order by
>>rowid asc;
>>Run Time: real 13.658 user 10.000000 sys 3.656250
>>sqlite> create temp table tdesc1 as select rowid from test order by
>>rowid desc;
>>Run Time: real 12.658 user 9.500000 sys 3.156250
>>sqlite> create temp table tasc2 as select rowid from test order by
>>rowid asc;
>>Run Time: real 13.017 user 10.031250 sys 2.984375
>>sqlite> create temp table tdesc2 as select rowid from test order by
>>rowid desc;
>>Run Time: real 13.001 user 9.750000 sys 3.250000
>>sqlite> .exit
>>
>>
>>2018-06-14 13:47:30 PY2 [D:\]
>>>dir junk.db
>>2018-06-14  13:44     4,450,889,728 junk.db
>>               1 File(s)  4,450,889,728 bytes
>>               0 Dir(s)  330,480,447,488 bytes free
>>
>>So we have some difference in SYS time for I/O, but that is about
>it.
>>Still constant times.
>>
>>---
>>The fact that there's a Highway to Hell but only a Stairway to
>Heaven
>>says a lot about anticipated traffic volume.
>>
>>
>>>-----Original Message-----
>>>From: sqlite-users [mailto:sqlite-users-
>>>[hidden email]] On Behalf Of x
>>>Sent: Thursday, 14 June, 2018 12:31
>>>To: SQLite mailing list
>>>Subject: Re: [sqlite] .timer
>>>
>>>Thanks for the replies. It is Windows Defender I’m using on a ms
>>>surface pro 4 with 16 GB ram and 512 GB SSD. OS is Windows 10 Pro.
>>>I’ve come up with the following demo using the sqlite shell. In it
>I
>>>use a couple of small apps called AvlRAM and FlushMem. Apart from
>>>minor background tasks sqlite3.exe is the only app running.
>>>
>>>I downloaded FlushMem from here https://chadaustin.me/flushmem/ and
>>>changed it slightly so that it reported the available RAM before
>and
>>>after the flush. I was primarily interested in how sqlite was
>>>performing after restarting the computer before any info was lying
>>>about in caches as I was encountering some strange timings with
>>such.
>>>FlushMem saved me from continually rebooting and yielded results
>>>similar to the ones I was experiencing with rebooting.
>>>
>>>The code for AvlRAM is as follows
>>>
>>>double FreeGBs()
>>>{
>>>        MEMORYSTATUSEX status;
>>>        status.dwLength = sizeof(status);
>>>        GlobalMemoryStatusEx(&status);
>>>        return status.ullAvailPhys / (1024.0 * 1024 * 1024);
>>>}
>>>
>>>int _tmain(int argc, _TCHAR* argv[])
>>>{
>>>        std::cout << FreeGBs() << " GBs" << std::endl;
>>>        return 0;
>>>}
>>>
>>>
>>>Here’s the demo interspersed with comments
>>>
>>>SQLite version 3.24.0 2018-06-04 19:24:41
>>>Enter ".help" for usage hints.
>>>Connected to a transient in-memory database.
>>>Use ".open FILENAME" to reopen on a persistent database.
>>>sqlite> .timer on
>>>sqlite> .open MyTemp.db -- open empty DB
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 12.913 GBs - post flush = 14.1749 GBs
>>>
>>>sqlite> create table test as -- creates test table with 100 million
>>>rows
>>>   ...> with recursive cte(x,y) as
>>>   ...> (values(1,'012345678901234567890123456789')
>>>   ...> union all select x+1,y from cte where x<100000000)
>>>   ...> select * from cte;
>>>Run Time: real 77.239 user 68.750000 sys 7.468750
>>>sqlite> .shell AvlRAM
>>>14.1059 GBs
>>>
>>>sqlite> create temp table tasc as select RowID from test order by
>>>RowID;
>>>Run Time: real 32.473 user 25.203125 sys 7.203125
>>>sqlite> .shell AvlRAM
>>>14.1084 GBs
>>>// little change to RAM, respectable time
>>>
>>>sqlite> create temp table tdesc as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 32.056 user 24.515625 sys 7.531250
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 9.96339 GBs - post flush = 14.7108 GBs
>>>// why does the RAM drop 4+ GB due to executing the above?,
>>>respectable time
>>>
>>>
>>>sqlite> create temp table tasc2 as select RowID from test order by
>>>RowID;
>>>Run Time: real 38.285 user 26.109375 sys 9.000000
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 14.5936 GBs - post flush = 14.7553 GBs
>>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>>still respectable
>>>
>>>sqlite> create temp table tdesc2 as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 117.765 user 28.265625 sys 13.828125
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 10.5519 GBs - post flush = 14.6888 GBs
>>>// RAM drops 4+ GB, time is woeful. Why?
>>>
>>>// repeat above 2 ‘create temp table’ commands to demonstrate not
>>>fluke
>>>
>>>sqlite> create temp table tasc3 as select RowID from test order by
>>>RowID;
>>>Run Time: real 41.747 user 26.562500 sys 10.625000
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 14.78 GBs - post flush = 14.754 GBs
>>>// no change to RAM, time a bit more sluggish after ‘reboot’ but
>>>still respectable
>>>
>>>sqlite> create temp table tdesc3 as select RowID from test order by
>>>RowID desc;
>>>Run Time: real 118.282 user 29.406250 sys 13.765625
>>>sqlite> .shell FlushMem
>>>Available RAM - pre flush = 10.6947 GBs - post flush = 14.5856 GBs
>>>// RAM drops 4- GB, time is woeful. Why?
>>>
>>>sqlite> .exit
>>>
>>>
>>>
>>>Why is using ‘RowID desc’ so much slower than ‘RowID asc’ after a
>>>‘reboot’? I get the impression Windows is caching the pages from
>the
>>>‘desc’ but not the ‘asc’ and that’s what’s slowing it down. On this
>>>particular journey I’ve come across tables where the reverse was
>the
>>>case (I.e. it was the ‘asc’ that was woefully slow).
>>>
>>>Anyone cast any light on this?
>>>_______________________________________________
>>>sqlite-users mailing list
>>>[hidden email]
>>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-
>users
>>
>>
>>
>>_______________________________________________
>>sqlite-users mailing list
>>[hidden email]
>>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>
>
>
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>_______________________________________________
>sqlite-users mailing list
>[hidden email]
>http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users



_______________________________________________
sqlite-users mailing list
[hidden email]
http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
123