Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Use non-synchronized getTimeZone in TimestampUtils #2451

Merged
merged 1 commit into from Feb 16, 2022
Merged

Use non-synchronized getTimeZone in TimestampUtils #2451

merged 1 commit into from Feb 16, 2022

Conversation

TeslaCN
Copy link
Contributor

@TeslaCN TeslaCN commented Feb 11, 2022 •
edited

Fixes #2450.

All Submissions:

  • Have you followed the guidelines in our Contributing document?
  • Have you checked to ensure there aren't other open Pull Requests for the same update/change?

Changes to Existing Features:

  • Have you successfully run tests with your changes locally?

@TeslaCN
Copy link
Contributor Author

TeslaCN commented Feb 11, 2022

Before

# JMH version: 1.33
# VM version: JDK 1.8.0_312, OpenJDK 64-Bit Server VM, 25.312-b07
# VM invoker: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.312.b07-1.el7_9.x86_64/jre/bin/java
# VM options: -Dfile.encoding=UTF-8
# Blackhole mode: full + dont-inline hint (default, use -Djmh.blackhole.autoDetect=true to auto-detect)
# Warmup: 5 iterations, 3 s each
# Measurement: 5 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 48 threads, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp

# Run progress: 0.00% complete, ETA 00:01:30
# Fork: 1 of 3
# Warmup Iteration   1: 1746.646 ops/ms
# Warmup Iteration   2: 1747.132 ops/ms
# Warmup Iteration   3: 1516.384 ops/ms
# Warmup Iteration   4: 1642.476 ops/ms
# Warmup Iteration   5: 1830.407 ops/ms
Iteration   1: 1766.497 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 1805.030 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 1850.128 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 1800.074 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 1783.444 ops/ms
                 ·stack: <delayed till summary>


# Run progress: 33.33% complete, ETA 00:01:12
# Fork: 2 of 3
# Warmup Iteration   1: 1562.776 ops/ms
# Warmup Iteration   2: 1636.858 ops/ms
# Warmup Iteration   3: 1694.104 ops/ms
# Warmup Iteration   4: 1625.119 ops/ms
# Warmup Iteration   5: 1669.645 ops/ms
Iteration   1: 1729.345 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 1646.023 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 1697.978 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 1587.859 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 1822.360 ops/ms
                 ·stack: <delayed till summary>


# Run progress: 66.67% complete, ETA 00:00:33
# Fork: 3 of 3
# Warmup Iteration   1: 1455.495 ops/ms
# Warmup Iteration   2: 1800.077 ops/ms
# Warmup Iteration   3: 1559.716 ops/ms
# Warmup Iteration   4: 1748.545 ops/ms
# Warmup Iteration   5: 1791.360 ops/ms
Iteration   1: 1993.977 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 2024.605 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 1935.053 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 1597.901 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 1814.908 ops/ms
                 ·stack: <delayed till summary>



Result "icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp":
  1790.346 ±(99.9%) 138.368 ops/ms [Average]
  (min, avg, max) = (1587.859, 1790.346, 2024.605), stdev = 129.430
  CI (99.9%): [1651.977, 1928.714] (assumes normal distribution)

Secondary result "icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp:·stack":
Stack profiler:

....[Thread state distributions]....................................................................
 95.4%         BLOCKED
  2.2%         RUNNABLE
  2.0%         TIMED_WAITING
  0.4%         WAITING

....[Thread state: BLOCKED].........................................................................
 95.4% 100.0% java.util.TimeZone.getTimeZone

....[Thread state: RUNNABLE]........................................................................
  2.0%  93.9% java.util.TimeZone.getTimeZone
  0.0%   1.2% java.util.GregorianCalendar.computeFields
  0.0%   0.6% org.openjdk.jmh.util.Deduplicator.dedup
  0.0%   0.4% sun.util.calendar.Gregorian.newCalendarDate
  0.0%   0.3% java.util.Calendar.<init>
  0.0%   0.3% org.postgresql.jdbc.PgConnection.prepareStatement
  0.0%   0.3% org.postgresql.jdbc.TimestampUtils.<init>
  0.0%   0.2% java.util.TimeZone.clone
  0.0%   0.2% org.postgresql.core.v3.SimpleParameterList.<init>
  0.0%   0.2% java.util.Arrays.copyOf
  0.0%   2.3% <other>

....[Thread state: TIMED_WAITING]...................................................................
  2.0% 100.0% java.lang.Object.wait

....[Thread state: WAITING].........................................................................
  0.4% 100.0% sun.misc.Unsafe.park



# Run complete. Total time: 00:01:38

REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.

Benchmark                                               Mode  Cnt     Score     Error   Units
PgPreparedStatementBenchmark.benchSetTimestamp         thrpt   15  1790.346 ± 138.368  ops/ms
PgPreparedStatementBenchmark.benchSetTimestamp:·stack  thrpt            NaN               ---

@TeslaCN
Copy link
Contributor Author

TeslaCN commented Feb 11, 2022

After

# JMH version: 1.33
# VM version: JDK 1.8.0_312, OpenJDK 64-Bit Server VM, 25.312-b07
# VM invoker: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.312.b07-1.el7_9.x86_64/jre/bin/java
# VM options: -Dfile.encoding=UTF-8
# Blackhole mode: full + dont-inline hint (default, use -Djmh.blackhole.autoDetect=true to auto-detect)
# Warmup: 5 iterations, 3 s each
# Measurement: 5 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 48 threads, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp

# Run progress: 0.00% complete, ETA 00:01:30
# Fork: 1 of 3
# Warmup Iteration   1: 7347.464 ops/ms
# Warmup Iteration   2: 9123.981 ops/ms
# Warmup Iteration   3: 11262.380 ops/ms
# Warmup Iteration   4: 11793.696 ops/ms
# Warmup Iteration   5: 11677.781 ops/ms
Iteration   1: 11876.898 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 11655.988 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 11757.058 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 12101.528 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 11796.924 ops/ms
                 ·stack: <delayed till summary>


# Run progress: 33.33% complete, ETA 00:01:03
# Fork: 2 of 3
# Warmup Iteration   1: 7721.356 ops/ms
# Warmup Iteration   2: 10055.440 ops/ms
# Warmup Iteration   3: 11200.962 ops/ms
# Warmup Iteration   4: 10891.638 ops/ms
# Warmup Iteration   5: 10067.917 ops/ms
Iteration   1: 10758.791 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 10709.973 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 11008.897 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 10993.436 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 11050.185 ops/ms
                 ·stack: <delayed till summary>


# Run progress: 66.67% complete, ETA 00:00:34
# Fork: 3 of 3
# Warmup Iteration   1: 7541.691 ops/ms
# Warmup Iteration   2: 8077.418 ops/ms
# Warmup Iteration   3: 11227.549 ops/ms
# Warmup Iteration   4: 11047.495 ops/ms
# Warmup Iteration   5: 11251.810 ops/ms
Iteration   1: 10972.230 ops/ms
                 ·stack: <delayed till summary>

Iteration   2: 10745.275 ops/ms
                 ·stack: <delayed till summary>

Iteration   3: 10836.037 ops/ms
                 ·stack: <delayed till summary>

Iteration   4: 10645.476 ops/ms
                 ·stack: <delayed till summary>

Iteration   5: 10385.107 ops/ms
                 ·stack: <delayed till summary>



Result "icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp":
  11152.920 ±(99.9%) 572.247 ops/ms [Average]
  (min, avg, max) = (10385.107, 11152.920, 12101.528), stdev = 535.280
  CI (99.9%): [10580.673, 11725.167] (assumes normal distribution)

Secondary result "icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp:·stack":
Stack profiler:

....[Thread state distributions]....................................................................
 97.3%         RUNNABLE
  2.0%         TIMED_WAITING
  0.6%         WAITING

....[Thread state: RUNNABLE]........................................................................
 33.8%  34.7% sun.util.calendar.ZoneInfo.getTransitionIndex
 10.6%  10.8% java.util.HashMap.hash
  8.1%   8.3% java.util.GregorianCalendar.computeFields
  4.2%   4.4% org.postgresql.jdbc.TimestampUtils.appendTime
  4.0%   4.1% java.util.Calendar.<init>
  2.8%   2.9% org.postgresql.jdbc.TimestampUtils.<init>
  2.5%   2.6% org.postgresql.jdbc.PgConnection.prepareStatement
  2.4%   2.5% icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.tearDown
  2.4%   2.4% icu.wwj.jmh.jdbc.PgPreparedStatementBenchmark.benchSetTimestamp
  2.2%   2.3% org.postgresql.jdbc.TimestampUtils.toString
 24.4%  25.0% <other>

....[Thread state: TIMED_WAITING]...................................................................
  2.0% 100.0% java.lang.Object.wait

....[Thread state: WAITING].........................................................................
  0.6% 100.0% sun.misc.Unsafe.park



# Run complete. Total time: 00:01:40

REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.

Benchmark                                               Mode  Cnt      Score     Error   Units
PgPreparedStatementBenchmark.benchSetTimestamp         thrpt   15  11152.920 ± 572.247  ops/ms
PgPreparedStatementBenchmark.benchSetTimestamp:·stack  thrpt             NaN               ---

@TeslaCN TeslaCN marked this pull request as ready for review February 11, 2022 03:38
@davecramer
Copy link
Member

Wow, who knew.. that was pretty simple. Thanks for the PR

@TeslaCN
Copy link
Contributor Author

TeslaCN commented Feb 16, 2022

Hi @davecramer
Can we fix this in 42.3.3?

@davecramer davecramer merged commit beeabe2 into pgjdbc:master Feb 16, 2022
@davecramer
Copy link
Member

It will be in the next release 42.3.4

@TeslaCN TeslaCN deleted the 2450 branch February 16, 2022 10:12
@TeslaCN
Copy link
Contributor Author

TeslaCN commented Feb 16, 2022

It will be in the next release 42.3.4

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@vlsi vlsi vlsi approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Concurrent performance issue in 42.3.2 caused by #2291
3 participants
@TeslaCN @davecramer @vlsi