You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-commits@db.apache.org by Apache Wiki <wi...@apache.org> on 2006/11/02 14:15:58 UTC

[Db-derby Wiki] Update of "Derby1961ResourceUsage2" by KnutAndersHatlen

Dear Wiki user,

You have subscribed to a wiki page or wiki category on "Db-derby Wiki" for change notification.

The following page has been changed by KnutAndersHatlen:
http://wiki.apache.org/db-derby/Derby1961ResourceUsage2

New page:
== Resource Usage in Derby ==

This page contains results found when investigating Derby's resource
usage ([http://issues.apache.org/jira/browse/DERBY-1961 DERBY-1961]).
If you have numbers you want to share, please add them
to the Results section at the end.

The Derby version tested is 10.2.1.6.

=== Load ===

The testing uses the load clients in
[http://issues.apache.org/jira/browse/DERBY-1961 DERBY-1961]. They are
able to perform three kinds of operations:

  1. Single-record select operations. Each transaction reads one row from a table of 100000 rows (each row is around 100 bytes).
  1. Single-record update operations. Each transaction updates one row in a table of 100000 rows (the same table as the select operations).
  1. Join operations. Joins one table of 10000 rows with a table of 1000 rows. The result contains 1000 rows.

All three load types access the rows by primary key.

The tests are run as client/server tests so that the resource usage of
the network server can be compared to the amount of resources used by
the other parts of Derby. To make sure that the page cache can hold
the entire database, increase the page cache size by starting the
network server with `-Dderby.storage.pageCacheSize=12500`.

=== Modules ===

When looking at where Derby consumes resources, it helps to divide the
code into modules or layers. Since the Derby code already is
structured in packages, the modules could be defined in terms of the
code packages:

|| '''Module'''   || '''Derby package''' ||
|| Network server || `org.apache.derby.drda` and `org.apache.derby.impl.drda` ||
|| JDBC           || `org.apache.derby.jdbc` and `org.apache.derby.impl.jdbc` ||
|| Execution      || `org.apache.derby.impl.sql` ||
|| Access         || `org.apache.derby.impl.store.access` ||
|| Lock manager   || `org.apache.derby.impl.services.locks` ||
|| Buffer manager || `org.apache.derby.impl.services.cache` ||
|| Logging        || `org.apache.derby.impl.store.raw.log` ||
|| Data store     || `org.apache.derby.impl.store.raw.data` ||
|| Transaction control || `org.apache.derby.impl.store.raw.xact` ||

=== Results ===

==== CPU and wall clock time ====

These results were obtained using a byte code instrumentation tool.
The CPU times include both system and user CPU.
The runs were done on a Solaris 10 machine with x86 hardware. Wall clock time
were obtained using ''gethrtime'' and the CPU times using ''getrusage''. [[BR]]
The test client was run with Java SE 6 (build 103), 35 seconds of warmup and 120 seconds runtime ("steady state").

'''Numbers are under validation. They might change!'''

|| ||<-2> '''Single-record select (10 clients)''' ||<-2> '''Single-record update (20 clients)''' ||<-2> '''Join (4 clients)''' ||
|| '''Module''' || '''System & user CPU''' || '''Wall clock time''' || '''System & user CPU''' || '''Wall clock time''' || '''System & user CPU''' || '''Wall clock time''' ||
|| Network server ||<style="text-align: right;"> 13.4% ||<style="text-align: right;"> 72.2% ||<style="text-align: right;">  9.0% ||<style="text-align: right;"> 24.8% ||<style="text-align: right;">  1.4% ||<style="text-align: right;">  1.5% ||
|| JDBC ||<style="text-align: right;">  4.1% ||<style="text-align: right;">  1.2% ||<style="text-align: right;">  0.9% ||<style="text-align: right;">  0.2% ||<style="text-align: right;">  2.2% ||<style="text-align: right;">  1.1% ||
|| Execution ||<style="text-align: right;">  7.8% ||<style="text-align: right;">  2.1% ||<style="text-align: right;">  8.4% ||<style="text-align: right;">  1.4% ||<style="text-align: right;">  5.0% ||<style="text-align: right;">  3.1% ||
|| Access ||<style="text-align: right;"> 18.2% ||<style="text-align: right;">  4.6% ||<style="text-align: right;"> 13.2% ||<style="text-align: right;">  2.4% ||<style="text-align: right;"> 30.0% ||<style="text-align: right;"> 17.7% ||
|| Lock manager ||<style="text-align: right;"> 20.8% ||<style="text-align: right;"> 11.7% ||<style="text-align: right;"> 23.1% ||<style="text-align: right;"> 15.0% ||<style="text-align: right;"> 15.8% ||<style="text-align: right;"> 40.9% ||
|| Buffer manager ||<style="text-align: right;">  8.0% ||<style="text-align: right;">  1.9% ||<style="text-align: right;">  6.6% ||<style="text-align: right;">  1.0% ||<style="text-align: right;">  1.2% ||<style="text-align: right;">  0.8% ||
|| Logging ||<style="text-align: right;">  0.0% ||<style="text-align: right;">  0.0% ||<style="text-align: right;"> 10.5% ||<style="text-align: right;"> 51.5% ||<style="text-align: right;">  0.0% ||<style="text-align: right;">  0.0% ||
|| Data store ||<style="text-align: right;"> 22.5% ||<style="text-align: right;">  5.1% ||<style="text-align: right;"> 21.3% ||<style="text-align: right;">  2.7% ||<style="text-align: right;"> 33.2% ||<style="text-align: right;"> 26.1% ||
|| Transaction control ||<style="text-align: right;">  5.1% ||<style="text-align: right;">  1.3% ||<style="text-align: right;">  7.0% ||<style="text-align: right;">  1.0% ||<style="text-align: right;"> 11.2% ||<style="text-align: right;">  8.8% ||


==== Object allocations ====

These results have been found by running the JVM (Java SE 6.0 - build
1.6.0-rc-b102) with the `-agentlib:hprof=heap=sites,...` option and
analysing the stack traces that were dumped.  The numbers are not very
accurate (in particular the join results), but they should at least give
an impression of how much memory each module allocates.

|| '''Module'''   ||<-2> '''Single-record select (10 clients)''' ||<-2> '''Single-record update (20 clients)''' ||<-2> '''Join (4 clients)''' ||
|| Network server ||<style="text-align: right;"> 905 B/tx ||<style="text-align: right;"> 15 objs/tx ||<style="text-align: right;"> 586 B/tx ||<style="text-align: right;"> 13 objs/tx ||<style="text-align: right;"> 68 B/tx ||<style="text-align: right;"> 4 objs/tx ||
|| JDBC           ||<style="text-align: right;"> 416 B/tx ||<style="text-align: right;"> 5 objs/tx || || ||<style="text-align: right;"> 176 B/tx ||<style="text-align: right;"> 3 objs/tx ||
|| Execution      ||<style="text-align: right;"> 1265 B/tx ||<style="text-align: right;"> 21 objs/tx ||<style="text-align: right;"> 2041 B/tx ||<style="text-align: right;"> 33 objs/tx ||<style="text-align: right;"> 1625 B/tx ||<style="text-align: right;"> 24 objs/tx ||
|| Access         ||<style="text-align: right;"> 840 B/tx ||<style="text-align: right;"> 25 objs/tx ||<style="text-align: right;"> 921 B/tx ||<style="text-align: right;"> 28 objs/tx ||<style="text-align: right;"> 110756 B/tx ||<style="text-align: right;"> 4093 objs/tx ||
|| Lock manager   ||<style="text-align: right;"> 579 B/tx ||<style="text-align: right;"> 23 objs/tx ||<style="text-align: right;">  707 B/tx ||<style="text-align: right;"> 29 objs/tx ||<style="text-align: right;"> 42874 B/tx ||<style="text-align: right;"> 1774 objs/tx||
|| Buffer manager ||  || || || || || ||
|| Logging        ||  || ||<style="text-align: right;"> 93 B/tx ||<style="text-align: right;"> 3 objs/tx || || ||
|| Data store     ||<style="text-align: right;"> 1099 B/tx ||<style="text-align: right;"> 30 objs/tx ||<style="text-align: right;"> 1327 B/tx ||<style="text-align: right;"> 36 objs/tx ||<style="text-align: right;"> 92658 B/tx ||<style="text-align: right;"> 22960 objs/tx ||
|| Transaction control ||<style="text-align: right;"> 80 B/tx ||<style="text-align: right;"> 3 objs/tx ||<style="text-align: right;">  136 B/tx ||<style="text-align: right;"> 6 objs/tx ||<style="text-align: right;"> 80 B/tx ||<style="text-align: right;"> 3 objs/tx ||

==== Garbage collection ====

The next table shows how much of the CPU is spent on garbage
collection. Platform: Java SE 6.0 - build 1.6.0-rc-b103, Solaris 10,
dual CPU. The numbers were collected using the GC probes in DTrace.

|| '''VM'''  || '''Single-record select (10 clients)''' || '''Single-record update (20 clients)''' || '''Join (4 clients)''' ||
|| Server VM || 3.8% || 0.05% || 0.04% ||
|| Client VM || 5.8% || 2.7%  || 1.4% ||

CPU spent on GC when the tests were run on a single-CPU machine:

|| '''VM'''  || '''Single-record select (10 clients)''' || '''Single-record update (20 clients)''' || '''Join (4 clients)''' ||
|| Server VM || 13% || (not tested) || (not tested) ||
|| Client VM || 11% || 3.7%  || 2.4% ||

==== System calls ====

Results found by logging all system calls on the database server with DTrace.

|| '''Module'''        || '''Single-record select (10 clients)''' || '''Single-record update (20 clients)''' || '''Join (4 clients)''' ||
|| Network server      || 4.0 scl/tx                              || 4.0 scl/tx                              ||  4.2 scl/tx            ||
|| JDBC                ||                                         ||                                         ||                        ||
|| Execution           ||                                         ||                                         ||                        ||
|| Access              ||                                         ||                                         ||  3.7 scl/tx            ||
|| Lock manager        || 1.9 scl/tx                              || 0.6 scl/tx                              || 26.4 scl/tx            ||
|| Buffer manager      ||                                         ||                                         ||  1.2 scl/tx            ||
|| Logging             ||                                         || 2.0 scl/tx                              ||                        ||
|| Data store          ||                                         || 0.4 scl/tx                              ||  0.5 scl/tx            ||
|| Transaction control ||                                         ||                                         ||                        ||
|| Unknown             ||                                         ||                                         ||  7.2 scl/tx            ||


==== Context switches ====

The results in the following table have been found by logging all
context switches on the database server with DTrace. There are two
kinds of context switches:

  * voluntary context switches, which means the thread gives the CPU
  to another thread voluntarily (e.g., blocking reads, calls to
  `Object.wait()` or attempts to lock a monitor which is locked by
  another thread)
  * involuntary context switches, which means that a thread is
  preempted by the scheduler (because its time quantum has expired)

All the numbers are context switches per transaction.

|| '''Module'''        ||<-2> '''Single-record select (10 clients)''' ||<-2> '''Single-record update (20 clients)''' ||<-2> '''Join (4 clients)''' ||
|| ||<style="text-align: center;"> '''Voluntary''' ||<style="text-align: center;"> '''Involuntary''' ||<style="text-align: center;"> '''Voluntary''' ||<style="text-align: center;"> '''Involuntary''' ||<style="text-align: center;"> '''Voluntary''' ||<style="text-align: center;"> '''Involuntary'''||
|| Network server      ||<style="text-align: center;">   2.0   ||<style="text-align: center;">  0.0       ||<style="text-align: center;">   2.0      ||<style="text-align: center;">     0.0    ||<style="text-align: center;">   2.0      ||<style="text-align: center;">    0.0     ||
|| JDBC                ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||
|| Execution           ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">    0.0     ||<style="text-align: center;">  0.6       ||
|| Access              ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">    0.0     ||<style="text-align: center;">  0.5       ||
|| Lock manager        ||<style="text-align: center;">   0.4   ||<style="text-align: center;">   0.1      ||<style="text-align: center;">   0.3      ||<style="text-align: center;">  0.1       ||<style="text-align: center;">   7.3      ||<style="text-align: center;">   2.9      ||
|| Buffer manager      ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">   0.1      ||<style="text-align: center;">    0.2     ||
|| Logging             ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">    1.6     ||<style="text-align: center;">   0.3      ||<style="text-align: center;">         ||<style="text-align: center;">         ||
|| Data store          ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">    0.0     ||<style="text-align: center;">  0.6       ||
|| Transaction control ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">         ||<style="text-align: center;">    0.0     ||<style="text-align: center;">  0.1       ||
|| Unknown             ||<style="text-align: center;">      ||<style="text-align: center;">         ||<style="text-align: center;">    0.1  ||<style="text-align: center;">   0.0   ||<style="text-align: center;">   0.8   ||<style="text-align: center;">    0.0  ||


==== Disk Access ====

The results in the following table have been found by logging all
disk accesses on the database server with DTrace. There are two
types of disk access (No reads were observed. Disk accesses for select and join have been omitted):

  * Asynchronous write
  * Synchronous write

All the numbers are per transaction.

|| '''Module'''        ||<-2> '''Single-record update (20 clients)''' ||
|| ||<style="text-align: center;"> '''Async write''' ||<style="text-align: center;"> '''Sync write''' ||
|| Logging             ||<style="text-align: center;">  5.5E-6    ||<style="text-align: center;">    0.30     ||
|| Data store          ||<style="text-align: center;">  0.06    ||<style="text-align: center;">   6.7E-5 ||

==== Monitors and synchronization ====

The next table shows the number of times the test clients tried to
enter a contended monitor per transaction (as reported by the
`hotspot:::monitor-contended-enter` probe in DTrace), and the number
of times the clients slept on a synchronization object per transaction
(as reported by the `sched:::sleep` probe in DTrace).

Platform: Java SE 6.0 - build 1.6.0-rc-b103, Solaris 10, dual CPU.

|| '''Module'''        ||<-2> '''Single-record select (10 clients)''' ||<-2> '''Single-record update (20 clients)''' ||<-2> '''Join (4 clients)''' ||
|| ||<style="text-align: center;"> '''Contention''' ||<style="text-align: center;"> '''Sleep''' ||<style="text-align: center;"> '''Contention''' ||<style="text-align: center;"> '''Sleep''' ||<style="text-align: center;"> '''Contention''' ||<style="text-align: center;"> '''Sleep'''||
|| Network server      || || 2.0 || || 2.0 || || 2.0 ||
|| JDBC                || || || || || || ||
|| Execution           || || || || || || ||
|| Access              || || || 0.1 || || || ||
|| Lock manager        || 0.3 || 1.0 || 0.5 || 0.7 || 2.7 || 6.8 ||
|| Buffer manager      || 0.1 || || 0.1 || || 0.1 || 0.1 ||
|| Logging             || || || 0.2 || 1.9 || || ||
|| Data store          || || || || || || ||
|| Transaction control || 0.1 || || 0.1 || || || ||
|| Unknown             || || || || || || 0.8 ||

==== Profiling Results ====

Running the test client for 900 sec with the embedded driver and 2 clients. 
Only the two working threads have been profiled. Only methods that use more than 1% User CPU or have a "significant" Sync Wait Time or Sync Wait Count, have been included. 

|| Sorted by User CPU                 || Sorted by Sync Wait Time      ||
|| [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/select-top.txt Select] || [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/select-sync-top.txt Select] ||
|| [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/update-top.txt Update] || [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/update-sync-top.txt Update] ||
|| [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/join-top.txt Join]     || [http://wiki.apache.org/db-derby-data/attachments/Derby1961ResourceUsage/attachments/join-sync-top.txt Join]     ||

Profiling was done using Sun Studio11 collect and analyzer