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

testng hang at switching test cases when running test cases with high thread count #595

Open
gongchunlin opened this issue Jan 22, 2015 · 5 comments
Open

testng hang at switching test cases when running test cases with high thread count #595

gongchunlin opened this issue Jan 22, 2015 · 5 comments

Comments

@gongchunlin
Copy link

I run our web service API test cases (600+) with high thread count 40. I found the the test hang occasionally. After some investigation, I believe it happened when testng threads switched the test cases to execute.

From the stack trace I printed in the last executed test case before the test hanged, we found the threads hanged when accessing the HashMap object. Do testng threads access a shared HashMap when switching test cases? The HashMap object is not thread safe, and it may make the threads hang. Similar problems can be widely found by searching the Internet. Here is an example: https://netbeans.org/bugzilla/show_bug.cgi?id=111851

The experiments I did are:

  1. changed the test to run in a single thread, and the hang issue never happened (26 runs)
  2. checked the test thread logs, and all the thread logs show the test case completed when the job hanged: the hang happened between each test case execution
  3. added some debug info to report the test progress, and then hang happened before all test cases were executed. And the hang happened in random progress (one happened after 167 test case passed, and the other happened after 580 test case passed)
  4. print all thread stack trace after each test case. When the job hanged, the problem thread seemed to be in either of the below stack trace, which are different from the stack trace of normal jobs/threads
    --------stack trace 1 for the problem thread
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - pool-1-thread-34
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.HashMap.transfer(HashMap.java:584)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.HashMap.resize(HashMap.java:564)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.HashMap.addEntry(HashMap.java:851)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.HashMap.put(HashMap.java:484)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.annotations.JDK15AnnotationFinder.findAnnotation(JDK15AnnotationFinder.java:178)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.annotations.JDK15AnnotationFinder.findAnnotation(JDK15AnnotationFinder.java:103)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Parameters.findDataProvider(Parameters.java:327)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Parameters.findDataProvider(Parameters.java:265)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Parameters.handleParameters(Parameters.java:417)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Invoker.handleParameters(Invoker.java:1383)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Invoker.createParameters(Invoker.java:1075)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1180)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - java.lang.Thread.run(Thread.java:722)
    Jan 20 22:47:36 [pool-1-thread-8] INFO TestListener.java - Current successful test cases are: 167
    Jan 20 22:47:36 [pool-1-thread-8] INFO CommonYQATest.java - Tearing down test method...

--------stack trace 2 for the problem thread
http://thefactory.corp.yahoo.com:9999/jenkins/job/SearchQaAutoPush-Qrs-QA-2-API/514/consoleFull
http://thefactory.corp.yahoo.com:9999/jenkins/view/Search_QA_GSM/job/SearchQaAutoPush-Qrs-QA-2-API-40Threads/14/console
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - pool-1-thread-36
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - java.util.HashMap.getEntry(HashMap.java:446)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - java.util.HashMap.get(HashMap.java:405)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.annotations.JDK15AnnotationFinder.findAnnotation(JDK15AnnotationFinder.java:175)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.annotations.JDK15AnnotationFinder.findAnnotation(JDK15AnnotationFinder.java:103)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Parameters.findDataProvider(Parameters.java:327)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Parameters.findDataProvider(Parameters.java:265)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Parameters.handleParameters(Parameters.java:417)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Invoker.handleParameters(Invoker.java:1383)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Invoker.createParameters(Invoker.java:1075)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1180)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Jan 20 22:47:35 [pool-1-thread-26] INFO TestListener.java - java.lang.Thread.run(Thread.java:722)

--------stack trace of normal thread
http://thefactory.corp.yahoo.com:9999/jenkins/view/Search_QA_GSM/job/SearchQaAutoPush-Qrs-QA-2-API-40Threads/14/console
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - pool-1-thread-10
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - sun.misc.Unsafe.park(Native Method)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.lang.Thread.run(Thread.java:722)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - Reference Handler
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.lang.Object.wait(Native Method)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.lang.Object.wait(Object.java:503)
Jan 20 22:43:43 [pool-1-thread-5] INFO TestListener.java - java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
@gongchunlin
Copy link
Author

I used the latest testng 6.8.17

robert-cody pushed a commit to robert-cody/testng that referenced this issue Jul 10, 2015
Fix testng-team#595: TestNG hang at switching test cases when running…
1c5b66b 
… test cases with high thread count
@robert-cody
Copy link

The problem is here:

public class JDK15AnnotationFinder implements IAnnotationFinder {
...
private Map<Pair<Annotation, ?>, IAnnotation> m_annotations = Maps.newHashMap();
...
Synchronized map should be used.

@cbeust
Copy link
Collaborator

cbeust commented Jul 10, 2015

Good catch!

I just pushed a fix: f644d1e

In 10-15 minutes, the new snapshot should be published on in the snapshot repo (6.9.5-SNAPSHOT). Can you try it and report back?

Thanks!

@gongchunlin
Copy link
Author

Thanks for the fix! Actually, I already tried similar fix with Synchronized map and rebuilt the testng, and the problem never happened again.

@gongchunlin
Copy link
Author

Since I am not using testng at present, I am not able to try the new formal testng at present.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@cbeust @gongchunlin @robert-cody