Re: [sqlite4java] debugging sqlite4java performance on Ubuntu vs RHEL

[Daniel Halperin]

Addendum:

Wrapping the entire series of CREATE TABLE statements into a transaction helps: Mac time drops from ~82ms to ~68ms, and Ubuntu time drops from ~1s to ~207ms(!). But I still need to root-cause the reason that performance is so dramatically different across platforms.

Thanks,

Dan

On Sun, Apr 21, 2013 at 12:37 AM, <dhal...@cs.washington.edu> wrote:

Hi everyone,

I have a very odd problem. I run the exact same, extraordinarily simple sqlite4java-282 program on four different machines, and the time to complete varies from ~60ms to ~1 second.

- laptop running Mac OS X 10.8

- desktop running 32-bit Ubuntu 10.4

- server running 64-bit Ubuntu 12.10

- server running 64-bit RHEL

You can see the very short source code of the main program (and try it out! using this GitHub repo: https://github.com/dhalperi/sqlite-test) here: https://github.com/dhalperi/sqlite-test/blob/master/src/test/sqlite/Main.java#L64

All it does is time opening a database, a few CREATE TABLE statements, and then closing. There are a few intermediate print statements that time the execution to ensure it's not just opening and closing that cause the issue. You can see sample Mac and Ubuntu outputs below.

On Mac and RHEL it takes around 100 ms to run. On both Ubuntu machines it takes around a second(!!). I'm thoroughly stumped as to why this could be happening. In particular, the same JRE (Oracle Java 7u21) is on all 4 machines. The same JNILIB is used on the 64-bit ubuntu and the 64-bit RHEL. All the machines are completely idle. The filesystem is the same on the Ubuntu and RHEL servers (ext4). The disk speeds are comparable, seek times are short. Any other ideas?

Thanks! (output below)

Dan

Mac:

Apr 21, 2013 12:12:12 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: instantiated [/var/folders/m_/qltd_g_13qd1v5tvr4l6q2rc0000gn/T/temp5456065157583186690db]
Apr 21, 2013 12:12:12 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite4java-osx-10.4 from system path
Apr 21, 2013 12:12:12 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite 3.7.10, wrapper 0.2
Apr 21, 2013 12:12:12 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: opened 
108 ms 99 us 
112 ms 351 us 
Apr 21, 2013 12:12:12 AM com.almworks.sqlite4java.Internal log 
INFO: [sqlite] DB[1]: connection closed 
116 ms 687 us 

Ubuntu server

Apr 21, 2013 12:13:41 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: instantiated [/tmp/temp4525485152507069348db]
Apr 21, 2013 12:13:41 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite4java-linux-i386 from system path
Apr 21, 2013 12:13:41 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite 3.7.10, wrapper 0.2
Apr 21, 2013 12:13:41 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: opened
502 ms 934 us 662 ns
705 ms 487 us 365 ns
Apr 21, 2013 12:13:42 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: connection closed
916 ms 177 us 662 ns

RHEL server

Apr 21, 2013 12:20:27 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: instantiated [/tmp/temp2920981342866812331db]
Apr 21, 2013 12:20:27 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite4java-linux-amd64 from system path
Apr 21, 2013 12:20:27 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] Internal: loaded sqlite 3.7.10, wrapper 0.2
Apr 21, 2013 12:20:27 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: opened
84 ms 599 us 551 ns
92 ms 728 us 272 ns
Apr 21, 2013 12:20:27 AM com.almworks.sqlite4java.Internal log
INFO: [sqlite] DB[1]: connection closed

--
You received this message because you are subscribed to the Google Groups "sqlite4java" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sqlite4java...@googlegroups.com.
To post to this group, send email to sqlit...@googlegroups.com.
Visit this group at http://groups.google.com/group/sqlite4java?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[ser...@almworks.com]

Hello Dan,

 

Thanks – that’s an interesting question. Out of curiosity, I ran your test on Windows 7 x64, the result is about 100ms.

 

Given your observation, one can think that the reason is exceptionally long time it takes to commit a transaction. Why is that so on Ubuntu, I’ve no idea. Sqlite3 does fsync, as far as I know, maybe Ubuntu kernel is compiled with some options that make this operation long. You can try playing with sqlite’s PRAGMAs to influence how commit is made.

 

I see you have shell scripts for doing the same actions with sqlite3 directly – what times do you see there? (Could you try those scripts with exactly the same sqlite3 version?)

 

The version of sqlite3 compiled in sqlite4java is a bit outdated, we need to update it soon. Maybe there was a related issue fixed recently.

 

Kind regards,

Igor

[Stella Laurenzo]

Sounds potentially like our old friend, fsync. Perhaps check the mount and compile options of ext4 on each?

[Daniel Halperin]

Hi everyone,

Igor and Stella, I think you're both right.

First, difference vs command-line tools: I initially found that the command-line performance was somewhat different than the sqlite performance, and attributed it to the difference between versions (RHEL uses SQLite ~3.6, Ubuntu SQLite 3.7.14 or so), so I was loathe to include these results.

   - But I was doing some command-line experiments in an NFS-mounted folder, which breaks all integrity of the results. When using /tmp (ext4 on both), the results are the same as sqlite4java-282 across machines. So it's not the sqlite version in sqlite4java.

Mainly, I found out that our RHEL boxes use Linux kernel (2.6.32-358.2.1.el6.x86_64) and the Ubuntu boxes use Linux kernel (3.5.0-17-generic). According to some reports, the Linux ext modules changed around version 3.1 to stop pretending to fsync and actually fsync. So one kernel being < 3.1 and one being > 3.1 would indeed explain the issue!

As for why the Mac doesn't show this issue, who knows? Maybe it's because with the encrypted filesystem I use on the laptop, writes are buffered in some weird way.

Thanks again Stella, Igor, and everyone else!

Dan