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.

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

GH-40775: [Benchmarking][Java] Fix conbench timeout v2 #40929

Closed
wants to merge 8 commits into from

Conversation

vibhatha
Copy link
Collaborator

@vibhatha vibhatha commented Apr 2, 2024

Rationale for this change

This PR is continuing the work done in #40786.

What changes are included in this PR?

Improving build configs to resolve a memory issue in benchmarks.

Are these changes tested?

Tested via existing test cases, no explicit tests are added.
TBD if further tests are required.

Are there any user-facing changes?

No

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 2, 2024

@ursabot please benchmark lang=Java

@ursabot
Copy link

ursabot commented Apr 2, 2024

Benchmark runs are scheduled for commit b760135. Watch https://buildkite.com/apache-arrow and https://conbench.ursa.dev for updates. A comment will be posted here when the runs are complete.

@github-actions github-actions bot added the awaiting review Awaiting review label Apr 2, 2024
Copy link

Thanks for your patience. Conbench analyzed the 0 benchmarking runs that have been run so far on PR commit b760135.

None of the specified runs were found on the Conbench server.

The full Conbench report has more details.

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 2, 2024

@austin3dickey Could you please review this one? I am not sure why the report is shown as a failure, but in the dashbord it says it is passing.

@vibhatha vibhatha changed the title WIP: [Benchmarking][Java] Fix conbench timeout GH-40775: [Benchmarking][Java] Fix conbench timeout v2 Apr 2, 2024
@vibhatha vibhatha marked this pull request as ready for review April 2, 2024 08:28
@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 2, 2024

@ursabot please benchmark lang=Java

@ursabot
Copy link

ursabot commented Apr 2, 2024

Commit b760135 already has scheduled benchmark runs.

@austin3dickey
Copy link
Contributor

Yeah, looks like the build passed but no results were uploaded to Conbench. I will take a look.

@austin3dickey
Copy link
Contributor

austin3dickey commented Apr 2, 2024

@vibhatha I just ran another build that printed the stdout of the archery process. (Sorry it's not pretty -- all the newlines are represented in this build as \n, but it's still readable. You can download the log and do something like echo "$(cat arrow-bci-benchmark-on-ursa-thinkcentre-m75q_build_4717_run-benchmarks.log | head -10377 | tail -1)" > out.txt)

It looks like the content of the output JSON file was {'suites': [{'name': 'JavaBenchmark', 'benchmarks': []}]}. Could you look at the stdout and check why this is?

(We're running openjdk version "1.8.0_402")

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 3, 2024

@austin3dickey looking into the output

{
'type': 'BenchmarkGroupExecution', 
'id': 'b601127ce3d6465f8681656af958831a', 
'lang': 'Java', 
'name': 'java-micro', 
'options': '--iterations=1', 
'flags': {'language': 'Java'}, 
'benchmarkable_id': 'b76013517bf4e33adb5fb141aa0a08a641c7a99c', 
'run_id': '766c585f2508499eb71d4fb293495096', 
'run_name': 'pull request: 40929', 
'machine': 'ursa-thinkcentre-m75q', 
'process_pid': 1796466, 
'command': 'conbench java-micro --iterations=1 --run-id=$RUN_ID --run-name="$RUN_NAME" --run-reason="$RUN_REASON" --commit=b76013517bf4e33adb5fb141aa0a08a641c7a99c --src=/var/lib/buildkite-agent/builds/ursa-thinkcentre-m75q-1/apache-arrow/arrow-bci-benchmark-on-ursa-thinkcentre-m75q/arrow', 
'started_at': '2024-04-02 09:13:48.394338', 
'finished_at': '2024-04-02 09:26:09.620209', 
'total_run_time': '0:12:21.225871', 
'failed': False, 
'return_code': 0, 
'stderr': '', 
'total_machine_virtual_memory': 16142196736
}

I haven't actually seen logs before, but probably need to check with a passing benchmark with expected outcome.

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 3, 2024

@austin3dickey how to query a older passing benchmark for Java? I haven't done this before, could you please give me a few pointers. The goal is to check if something is wrong in the output. It says failure=False but we don't see the report.

@austin3dickey
Copy link
Contributor

@vibhatha Unfortunately we never printed the stdout/stderr of the archery process in the past because of the GBs of log output, so we don't have past logs to look at.

I think the critical line in that log is line 10377. I see a bunch of failures like the below. Not sure why the process exits 0, because no benchmarks are run due to these failures.

# JMH version: 1.37
# VM version: JDK 1.8.0_402, OpenJDK 64-Bit Server VM, 25.402-b06
# VM invoker: /usr/lib/jvm/java-8-openjdk-amd64/jre/bin/java
# VM options: -Darrow.enable_null_check_for_get=false -Darrow.enable_unsafe_memory_access=true
# Blackhole mode: full + dont-inline hint (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
# Warmup: 5 iterations, 10 s each
# Measurement: 1 iterations, 10 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: org.apache.arrow.vector.ipc.WriteChannelBenchmark.alignBenchmark
# Parameters: (alignSize = 5)

# Run progress: 87.50% complete, ETA 00:00:01
# Fork: 1 of 1
# Warmup Iteration   1: <failure>

java.lang.UnsupportedClassVersionError: ch/qos/logback/classic/spi/LogbackServiceProvider has been compiled by a more recent version of the Java Runtime (class file version 55.0), this version of the Java Runtime only recognizes class file versions up to 52.0
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:756)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:473)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:74)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:369)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:352)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:348)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:370)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at org.slf4j.LoggerFactory.safelyInstantiate(LoggerFactory.java:149)
	at org.slf4j.LoggerFactory.findServiceProviders(LoggerFactory.java:130)
	at org.slf4j.LoggerFactory.bind(LoggerFactory.java:191)
	at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:183)
	at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:486)
	at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:472)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:421)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:447)
	at org.apache.arrow.vector.ipc.WriteChannel.<clinit>(WriteChannel.java:45)
	at org.apache.arrow.vector.ipc.WriteChannelBenchmark$AlignState.prepareInvoke(WriteChannelBenchmark.java:61)
	at org.apache.arrow.vector.ipc.jmh_generated.WriteChannelBenchmark_alignBenchmark_jmhTest.alignBenchmark_avgt_jmhStub(WriteChannelBenchmark_alignBenchmark_jmhTest.java:395)
	at org.apache.arrow.vector.ipc.jmh_generated.WriteChannelBenchmark_alignBenchmark_jmhTest.alignBenchmark_AverageTime(WriteChannelBenchmark_alignBenchmark_jmhTest.java:313)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:527)
	at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:504)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)

@lidavidm
Copy link
Member

lidavidm commented Apr 3, 2024

That's fairly straightforward then. The logging library is too new for Java 8. (Do we need to enable logging at all?)

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 3, 2024

Probably we could fix this issue or disable logs. For benchmarks, wouldn't logs hurt performance?

@danepitkin
Copy link
Member

Probably we could fix this issue or disable logs. For benchmarks, wouldn't logs hurt performance?

According to our docs, if we do not specify a debug level, Arrow Java defaults to DEBUG level log printing.

To disable debug logs, the user must define their own rules within their logback.xml/log4j2.xml and define their own loggers.

https://arrow.apache.org/docs/developers/java/development.html#id2

@lidavidm
Copy link
Member

lidavidm commented Apr 3, 2024

We can use an older version then.

Though, what I meant is this point

If no jar dependencies are added by the user via Logback or Apache Log4j then SLF4J will default to no-operation (NOP) logging.

@vibhatha
Copy link
Collaborator Author

vibhatha commented Apr 6, 2024

Closing this PR since the issue was resolved in another PR.

@vibhatha vibhatha closed this Apr 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants