-
Bug
-
Resolution: Fixed
-
P4
-
6, 6u17
-
b70
-
generic, x86
-
generic, windows_xp
-
Verified
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-2186676 | 6u19 | Karunakar Gajjala | P3 | Resolved | Fixed | b01 |
JDK-2189209 | 6u18-rev | Karunakar Gajjala | P3 | Resolved | Fixed | b09 |
JDK-2182831 | 6u17-rev | Karunakar Gajjala | P3 | Closed | Fixed | b08 |
FULL PRODUCT VERSION :
Windows XP test: 1.6.0_b90 and 1.5.0_07
Solaris 5.11 test: 1.5.0_09
ADDITIONAL OS VERSION INFORMATION :
Windows XP, Intel Core Duo
Solaris 5.11 snv_37, Sun-Fire-V240
A DESCRIPTION OF THE PROBLEM :
Thread dump from Solaris showed looping on the remove with all four pool threads on line 312 from ConcurrentLinkedQueue for excessive amounts of time. Typical runs were within a second or two, I stopped after 10 minutes of 100% CPU usage.
"pool-3-thread-4" prio=10 tid=0x001632f8 nid=0x18 runnable [0xd4b7f000..0xd4b7f970]
at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:312)
at Test$Task.run(Test.java:102)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
The output from the execution on Windows which ran 20 times and locked up 3 times out of 20 is included in the actual results below. Also note that a couple of the size reports indicated in excess of 1 Million records which should be impossible (see iterations 2 and 10).
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Compile and run the included Test.java code.
EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Predictable results
ACTUAL -
Windows XP output for one of my test runs. Note the forced termination after 10 minutes of iterations 3, 9, 14. Also note the size reported in iteration 2 and iteration 10 which should be impossible given the test is on partitioned data set and order of actions.
$ uname -a
CYGWIN_NT-5.1 dan 1.5.19(0.150/4/2) 2006-01-20 13:28 i686 Cygwin
$ java -version
java version "1.6.0-rc"
Java(TM) SE Runtime Environment (build 1.6.0-rc-b90)
Java HotSpot(TM) Client VM (build 1.6.0-rc-b90, mixed mode, sharing)
$ java -server -Xmx500M -Xms500M Test
Starting... 0 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 626911
2 added - 804218
1 added - 757165
2 polled - 500000
0 polled - 519365
3 added - 703258
3 polled - 507740
1 polled - 500000
0 added - 507740
1 added - 819939
3 added - 999924
2 added - 1000000
0 remove - 678325
2 remove - 499078
1 remove - 177787
3 remove - 0
Completed: 1125 milliseconds, queue size=0
Starting... 1 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 629818
2 added - 978939
1 added - 656759
2 polled - 617590
1 polled - 377709
3 added - 760598
0 polled - 406280
2 added - 478282
3 polled - 500455
0 added - 495282
3 added - 716997
1 added - 866876
2 remove - 549977
0 remove - 377458
3 remove - 150955
1 remove - 0
Completed: 1313 milliseconds, queue size=0
Starting... 2 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 649555
2 added - 832458
0 polled - 750000
1 added - 841207
2 polled - 497643
1 polled - 510353
3 added - 1045219
0 added - 546253
3 polled - 299634
3 added - 783200
2 added - 880144
1 added - 848923
0 remove - 704093
3 remove - 97313
1 remove - 31145
2 remove - 0
Completed: 2328 milliseconds, queue size=0
Starting... 3 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
1 added - 762932
0 added - 805241
3 added - 805377
1 polled - 502980
3 polled - 465554
0 polled - 491524
2 added - 600157
3 added - 704917
0 added - 933826
1 added - 933828
2 polled - 749958
2 added - 999935
Termination took longer then 600 seconds!
queue size remaining = 936113, after clear size =
1 remove - 0
0 remove - 0
3 remove - 0
2 remove - 0
Starting... 4 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 950761
2 added - 980956
1 added - 927602
0 polled - 580831
2 polled - 526842
3 added - 835338
2 added - 599391
0 added - 685716
1 polled - 499998
3 polled - 552269
1 added - 658376
0 remove - 481605
3 added - 499740
2 remove - 498701
1 remove - 160885
3 remove - 0
Completed: 1422 milliseconds, queue size=0
Starting... 5 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 972580
3 added - 1000000
0 added - 1000000
1 added - 1000000
2 polled - 271522
0 polled - 110446
3 polled - 112068
1 polled - 350682
2 added - 756650
0 added - 902095
3 added - 867067
1 added - 872257
2 remove - 300264
0 remove - 132536
3 remove - 169140
1 remove - 0
Completed: 1828 milliseconds, queue size=0
Starting... 6 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 727127
2 added - 900321
3 added - 900321
0 polled - 730664
1 added - 905126
3 polled - 291136
1 polled - 226503
2 polled - 211202
3 added - 909437
0 added - 909437
2 added - 909436
1 added - 849379
2 remove - 137861
0 remove - 90558
3 remove - 97915
1 remove - 0
Completed: 3968 milliseconds, queue size=0
Starting... 7 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 974910
1 added - 993076
0 added - 998058
3 added - 1000000
1 polled - 480110
2 polled - 147727
3 polled - 148788
0 polled - 161765
1 added - 636328
0 added - 833290
3 added - 862670
2 added - 902863
1 remove - 411605
0 remove - 69627
3 remove - 39973
2 remove - 0
Completed: 2454 milliseconds, queue size=0
Starting... 8 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 945902
2 added - 1000000
3 added - 1000000
1 added - 1000000
0 polled - 335978
2 polled - 236408
3 polled - 308014
1 polled - 578056
2 added - 704479
0 added - 644293
1 added - 901217
3 added - 906853
0 remove - 402475
2 remove - 342513
1 remove - 34812
3 remove - 0
Completed: 2093 milliseconds, queue size=0
Starting... 9 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 900876
1 added - 903164
3 added - 903877
1 polled - 311523
2 polled - 268191
3 polled - 271855
1 added - 751537
3 added - 924198
2 added - 999998
0 added - 999997
0 polled - 749993
0 added - 999971
Termination took longer then 600 seconds!
queue size remaining = 821292, after clear size =
3 remove - 0
0 remove - 0
1 remove - 0
2 remove - 0
Starting... 10 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 879643
1 added - 897001
3 added - 644642
1 polled - 628203
0 added - 1069035
2 polled - 441923
1 added - 379686
0 polled - 417187
3 polled - 617264
2 added - 658182
3 added - 836310
0 added - 836311
1 remove - 749593
2 remove - 285153
0 remove - 14949
3 remove - 0
Completed: 1594 milliseconds, queue size=0
Starting... 11 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 831962
1 added - 824024
0 added - 818467
3 added - 581720
2 polled - 361940
0 polled - 484521
2 added - 394788
3 polled - 394788
1 polled - 645158
0 added - 947759
3 added - 947759
1 added - 947902
2 remove - 605171
1 remove - 71534
0 remove - 8562
3 remove - 0
Completed: 1578 milliseconds, queue size=0
Starting... 12 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 942036
2 added - 942036
3 added - 800840
2 polled - 623979
1 added - 1000000
0 polled - 260351
3 polled - 272436
0 added - 700303
1 polled - 697319
1 added - 950539
3 added - 706628
2 added - 999971
0 remove - 470932
3 remove - 330967
1 remove - 48979
2 remove - 0
Completed: 6266 milliseconds, queue size=0
Starting... 13 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
3 added - 986418
1 added - 1000000
0 added - 1000000
2 added - 1000000
1 polled - 211826
3 polled - 205749
1 added - 588754
3 added - 555473
2 polled - 555473
2 added - 635561
0 polled - 750000
0 added - 628431
1 remove - 546842
3 remove - 499272
2 remove - 249467
0 remove - 0
Completed: 2953 milliseconds, queue size=0
Starting... 14 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 885379
2 added - 861604
0 polled - 722099
1 added - 761634
3 added - 841902
2 polled - 401568
0 added - 350553
3 polled - 334076
1 polled - 539232
1 added - 1000000
2 added - 1000000
3 added - 999998
Termination took longer then 600 seconds!
queue size remaining = 819034, after clear size =
2 remove - 0
3 remove - 0
0 remove - 0
1 remove - 0
Starting... 15 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 655202
1 added - 719796
3 added - 748983
2 added - 744466
0 polled - 750000
2 polled - 153472
1 polled - 198947
3 polled - 217379
2 added - 897073
3 added - 959652
0 added - 999730
1 added - 1000000
2 remove - 137782
3 remove - 39915
1 remove - 121693
0 remove - 0
Completed: 4453 milliseconds, queue size=0
Starting... 16 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 913970
3 added - 925342
2 added - 780391
1 added - 780391
0 polled - 321855
2 polled - 149613
1 polled - 140342
3 polled - 387548
0 added - 678953
2 added - 705383
3 added - 900256
1 added - 900227
0 remove - 355552
2 remove - 275761
3 remove - 21863
1 remove - 0
Completed: 2641 milliseconds, queue size=0
Starting... 17 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 1000000
0 added - 1000000
3 added - 1000000
0 polled - 607566
1 added - 779056
2 polled - 466345
3 polled - 466392
1 polled - 446531
0 added - 528303
2 added - 594149
1 added - 805185
3 added - 804470
0 remove - 648768
2 remove - 426921
1 remove - 239110
3 remove - 0
Completed: 1359 milliseconds, queue size=0
Starting... 18 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 894523
0 added - 894523
1 added - 900752
3 added - 372738
2 polled - 372688
0 polled - 238114
3 polled - 128499
1 polled - 144965
2 added - 691538
0 added - 845329
3 added - 836802
1 added - 863104
2 remove - 375510
0 remove - 45167
3 remove - 26285
1 remove - 0
Completed: 2172 milliseconds, queue size=0
Starting... 19 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 819779
3 added - 941429
2 added - 888330
1 added - 930101
3 polled - 150232
0 polled - 149380
2 polled - 240260
1 polled - 491494
0 added - 723119
3 added - 623724
2 added - 821085
1 added - 893795
3 remove - 521341
0 remove - 329584
2 remove - 81874
1 remove - 0
Completed: 1750 milliseconds, queue size=0
Done...
REPRODUCIBILITY :
This bug can be reproduced always.
---------- BEGIN SOURCE ----------
import java.util.concurrent.*;
public class Test
{
public static void main(String arg[])
{
new Test().execute();
}
public void execute()
{
int numElements = 1000000;
int maxSecondsForTermination = 60*10;
String strings[] = new String[numElements];
for (int i = 0; i<numElements; i++ )
{
strings[i] = Integer.toString(i);
}
for (int iteration=0; iteration<20;iteration++)
{
// Wait for a couple seconds between runs to let the previous failures
// clear out.
try { Thread.sleep(1000*5); } catch ( Exception ex ) { }
System.out.println( "Starting... " + iteration + " iteration" );
ConcurrentLinkedQueue queue = new ConcurrentLinkedQueue();
Runnable[] tasks = new Task[4];
int size = strings.length/tasks.length;
for (int i = 0; i<tasks.length; i++ )
{
int s= i*size;
int e= s+size;
tasks[i] = new Task(i, queue, strings, s, e);
}
runTasks(iteration, maxSecondsForTermination, queue, tasks);
}
System.out.println( "Done..." );
}
public void runTasks(int iteration, int maxSecondsForTermination, ConcurrentLinkedQueue queue, Runnable[] tasks)
{
ThreadPoolExecutor e = (ThreadPoolExecutor)Executors.newFixedThreadPool(tasks.length);
e.prestartAllCoreThreads();
long start = System.currentTimeMillis();
for (int i=0;i<tasks.length;i++) {
e.execute(tasks[i]);
}
e.shutdown();
try {
if ( !e.awaitTermination(maxSecondsForTermination, TimeUnit.SECONDS) ) {
System.out.println( "Termination took longer then " + maxSecondsForTermination + " seconds!" );
System.out.print( "queue size remaining = " + queue.size() );
queue.clear();
System.out.println( ", after clear size = " + queue.size() );
} else {
long end = System.currentTimeMillis();
System.out.println( "Completed: " + (end-start) + " milliseconds, queue size=" + queue.size() );
}
} catch (Exception ex ) {
ex.printStackTrace();
}
}
static class Task implements Runnable
{
int id;
String[] strings;
int low;
int high;
ConcurrentLinkedQueue queue;
public Task(int id, ConcurrentLinkedQueue queue, String[] strings, int low, int high)
{
System.out.println( "Created Task(" + low +"," + high + ")" );
this.id = id;
this.strings = strings;
this.low = low;
this.high = high;
this.queue = queue;
}
public void run()
{
for (int i=low; i<high; i++) {
queue.add(strings[i]);
}
System.out.println( id + " added - " + queue.size() );
for (int i=low; i<high; i++) {
String s = (String)queue.poll();
}
System.out.println( id + " polled - " + queue.size() );
for (int i=low; i<high; i++) {
queue.add(strings[i]);
}
System.out.println( id + " added - " + queue.size() );
for (int i=low; i<high; i++) {
queue.remove(strings[i]);
}
System.out.println( id + " remove - " + queue.size() );
}
}
}
---------- END SOURCE ----------
Windows XP test: 1.6.0_b90 and 1.5.0_07
Solaris 5.11 test: 1.5.0_09
ADDITIONAL OS VERSION INFORMATION :
Windows XP, Intel Core Duo
Solaris 5.11 snv_37, Sun-Fire-V240
A DESCRIPTION OF THE PROBLEM :
Thread dump from Solaris showed looping on the remove with all four pool threads on line 312 from ConcurrentLinkedQueue for excessive amounts of time. Typical runs were within a second or two, I stopped after 10 minutes of 100% CPU usage.
"pool-3-thread-4" prio=10 tid=0x001632f8 nid=0x18 runnable [0xd4b7f000..0xd4b7f970]
at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:312)
at Test$Task.run(Test.java:102)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
The output from the execution on Windows which ran 20 times and locked up 3 times out of 20 is included in the actual results below. Also note that a couple of the size reports indicated in excess of 1 Million records which should be impossible (see iterations 2 and 10).
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Compile and run the included Test.java code.
EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Predictable results
ACTUAL -
Windows XP output for one of my test runs. Note the forced termination after 10 minutes of iterations 3, 9, 14. Also note the size reported in iteration 2 and iteration 10 which should be impossible given the test is on partitioned data set and order of actions.
$ uname -a
CYGWIN_NT-5.1 dan 1.5.19(0.150/4/2) 2006-01-20 13:28 i686 Cygwin
$ java -version
java version "1.6.0-rc"
Java(TM) SE Runtime Environment (build 1.6.0-rc-b90)
Java HotSpot(TM) Client VM (build 1.6.0-rc-b90, mixed mode, sharing)
$ java -server -Xmx500M -Xms500M Test
Starting... 0 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 626911
2 added - 804218
1 added - 757165
2 polled - 500000
0 polled - 519365
3 added - 703258
3 polled - 507740
1 polled - 500000
0 added - 507740
1 added - 819939
3 added - 999924
2 added - 1000000
0 remove - 678325
2 remove - 499078
1 remove - 177787
3 remove - 0
Completed: 1125 milliseconds, queue size=0
Starting... 1 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 629818
2 added - 978939
1 added - 656759
2 polled - 617590
1 polled - 377709
3 added - 760598
0 polled - 406280
2 added - 478282
3 polled - 500455
0 added - 495282
3 added - 716997
1 added - 866876
2 remove - 549977
0 remove - 377458
3 remove - 150955
1 remove - 0
Completed: 1313 milliseconds, queue size=0
Starting... 2 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 649555
2 added - 832458
0 polled - 750000
1 added - 841207
2 polled - 497643
1 polled - 510353
3 added - 1045219
0 added - 546253
3 polled - 299634
3 added - 783200
2 added - 880144
1 added - 848923
0 remove - 704093
3 remove - 97313
1 remove - 31145
2 remove - 0
Completed: 2328 milliseconds, queue size=0
Starting... 3 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
1 added - 762932
0 added - 805241
3 added - 805377
1 polled - 502980
3 polled - 465554
0 polled - 491524
2 added - 600157
3 added - 704917
0 added - 933826
1 added - 933828
2 polled - 749958
2 added - 999935
Termination took longer then 600 seconds!
queue size remaining = 936113, after clear size =
1 remove - 0
0 remove - 0
3 remove - 0
2 remove - 0
Starting... 4 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 950761
2 added - 980956
1 added - 927602
0 polled - 580831
2 polled - 526842
3 added - 835338
2 added - 599391
0 added - 685716
1 polled - 499998
3 polled - 552269
1 added - 658376
0 remove - 481605
3 added - 499740
2 remove - 498701
1 remove - 160885
3 remove - 0
Completed: 1422 milliseconds, queue size=0
Starting... 5 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 972580
3 added - 1000000
0 added - 1000000
1 added - 1000000
2 polled - 271522
0 polled - 110446
3 polled - 112068
1 polled - 350682
2 added - 756650
0 added - 902095
3 added - 867067
1 added - 872257
2 remove - 300264
0 remove - 132536
3 remove - 169140
1 remove - 0
Completed: 1828 milliseconds, queue size=0
Starting... 6 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 727127
2 added - 900321
3 added - 900321
0 polled - 730664
1 added - 905126
3 polled - 291136
1 polled - 226503
2 polled - 211202
3 added - 909437
0 added - 909437
2 added - 909436
1 added - 849379
2 remove - 137861
0 remove - 90558
3 remove - 97915
1 remove - 0
Completed: 3968 milliseconds, queue size=0
Starting... 7 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 974910
1 added - 993076
0 added - 998058
3 added - 1000000
1 polled - 480110
2 polled - 147727
3 polled - 148788
0 polled - 161765
1 added - 636328
0 added - 833290
3 added - 862670
2 added - 902863
1 remove - 411605
0 remove - 69627
3 remove - 39973
2 remove - 0
Completed: 2454 milliseconds, queue size=0
Starting... 8 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 945902
2 added - 1000000
3 added - 1000000
1 added - 1000000
0 polled - 335978
2 polled - 236408
3 polled - 308014
1 polled - 578056
2 added - 704479
0 added - 644293
1 added - 901217
3 added - 906853
0 remove - 402475
2 remove - 342513
1 remove - 34812
3 remove - 0
Completed: 2093 milliseconds, queue size=0
Starting... 9 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 900876
1 added - 903164
3 added - 903877
1 polled - 311523
2 polled - 268191
3 polled - 271855
1 added - 751537
3 added - 924198
2 added - 999998
0 added - 999997
0 polled - 749993
0 added - 999971
Termination took longer then 600 seconds!
queue size remaining = 821292, after clear size =
3 remove - 0
0 remove - 0
1 remove - 0
2 remove - 0
Starting... 10 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 879643
1 added - 897001
3 added - 644642
1 polled - 628203
0 added - 1069035
2 polled - 441923
1 added - 379686
0 polled - 417187
3 polled - 617264
2 added - 658182
3 added - 836310
0 added - 836311
1 remove - 749593
2 remove - 285153
0 remove - 14949
3 remove - 0
Completed: 1594 milliseconds, queue size=0
Starting... 11 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 831962
1 added - 824024
0 added - 818467
3 added - 581720
2 polled - 361940
0 polled - 484521
2 added - 394788
3 polled - 394788
1 polled - 645158
0 added - 947759
3 added - 947759
1 added - 947902
2 remove - 605171
1 remove - 71534
0 remove - 8562
3 remove - 0
Completed: 1578 milliseconds, queue size=0
Starting... 12 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 942036
2 added - 942036
3 added - 800840
2 polled - 623979
1 added - 1000000
0 polled - 260351
3 polled - 272436
0 added - 700303
1 polled - 697319
1 added - 950539
3 added - 706628
2 added - 999971
0 remove - 470932
3 remove - 330967
1 remove - 48979
2 remove - 0
Completed: 6266 milliseconds, queue size=0
Starting... 13 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
3 added - 986418
1 added - 1000000
0 added - 1000000
2 added - 1000000
1 polled - 211826
3 polled - 205749
1 added - 588754
3 added - 555473
2 polled - 555473
2 added - 635561
0 polled - 750000
0 added - 628431
1 remove - 546842
3 remove - 499272
2 remove - 249467
0 remove - 0
Completed: 2953 milliseconds, queue size=0
Starting... 14 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 885379
2 added - 861604
0 polled - 722099
1 added - 761634
3 added - 841902
2 polled - 401568
0 added - 350553
3 polled - 334076
1 polled - 539232
1 added - 1000000
2 added - 1000000
3 added - 999998
Termination took longer then 600 seconds!
queue size remaining = 819034, after clear size =
2 remove - 0
3 remove - 0
0 remove - 0
1 remove - 0
Starting... 15 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 655202
1 added - 719796
3 added - 748983
2 added - 744466
0 polled - 750000
2 polled - 153472
1 polled - 198947
3 polled - 217379
2 added - 897073
3 added - 959652
0 added - 999730
1 added - 1000000
2 remove - 137782
3 remove - 39915
1 remove - 121693
0 remove - 0
Completed: 4453 milliseconds, queue size=0
Starting... 16 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 913970
3 added - 925342
2 added - 780391
1 added - 780391
0 polled - 321855
2 polled - 149613
1 polled - 140342
3 polled - 387548
0 added - 678953
2 added - 705383
3 added - 900256
1 added - 900227
0 remove - 355552
2 remove - 275761
3 remove - 21863
1 remove - 0
Completed: 2641 milliseconds, queue size=0
Starting... 17 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 1000000
0 added - 1000000
3 added - 1000000
0 polled - 607566
1 added - 779056
2 polled - 466345
3 polled - 466392
1 polled - 446531
0 added - 528303
2 added - 594149
1 added - 805185
3 added - 804470
0 remove - 648768
2 remove - 426921
1 remove - 239110
3 remove - 0
Completed: 1359 milliseconds, queue size=0
Starting... 18 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
2 added - 894523
0 added - 894523
1 added - 900752
3 added - 372738
2 polled - 372688
0 polled - 238114
3 polled - 128499
1 polled - 144965
2 added - 691538
0 added - 845329
3 added - 836802
1 added - 863104
2 remove - 375510
0 remove - 45167
3 remove - 26285
1 remove - 0
Completed: 2172 milliseconds, queue size=0
Starting... 19 iteration
Created Task(0,250000)
Created Task(250000,500000)
Created Task(500000,750000)
Created Task(750000,1000000)
0 added - 819779
3 added - 941429
2 added - 888330
1 added - 930101
3 polled - 150232
0 polled - 149380
2 polled - 240260
1 polled - 491494
0 added - 723119
3 added - 623724
2 added - 821085
1 added - 893795
3 remove - 521341
0 remove - 329584
2 remove - 81874
1 remove - 0
Completed: 1750 milliseconds, queue size=0
Done...
REPRODUCIBILITY :
This bug can be reproduced always.
---------- BEGIN SOURCE ----------
import java.util.concurrent.*;
public class Test
{
public static void main(String arg[])
{
new Test().execute();
}
public void execute()
{
int numElements = 1000000;
int maxSecondsForTermination = 60*10;
String strings[] = new String[numElements];
for (int i = 0; i<numElements; i++ )
{
strings[i] = Integer.toString(i);
}
for (int iteration=0; iteration<20;iteration++)
{
// Wait for a couple seconds between runs to let the previous failures
// clear out.
try { Thread.sleep(1000*5); } catch ( Exception ex ) { }
System.out.println( "Starting... " + iteration + " iteration" );
ConcurrentLinkedQueue queue = new ConcurrentLinkedQueue();
Runnable[] tasks = new Task[4];
int size = strings.length/tasks.length;
for (int i = 0; i<tasks.length; i++ )
{
int s= i*size;
int e= s+size;
tasks[i] = new Task(i, queue, strings, s, e);
}
runTasks(iteration, maxSecondsForTermination, queue, tasks);
}
System.out.println( "Done..." );
}
public void runTasks(int iteration, int maxSecondsForTermination, ConcurrentLinkedQueue queue, Runnable[] tasks)
{
ThreadPoolExecutor e = (ThreadPoolExecutor)Executors.newFixedThreadPool(tasks.length);
e.prestartAllCoreThreads();
long start = System.currentTimeMillis();
for (int i=0;i<tasks.length;i++) {
e.execute(tasks[i]);
}
e.shutdown();
try {
if ( !e.awaitTermination(maxSecondsForTermination, TimeUnit.SECONDS) ) {
System.out.println( "Termination took longer then " + maxSecondsForTermination + " seconds!" );
System.out.print( "queue size remaining = " + queue.size() );
queue.clear();
System.out.println( ", after clear size = " + queue.size() );
} else {
long end = System.currentTimeMillis();
System.out.println( "Completed: " + (end-start) + " milliseconds, queue size=" + queue.size() );
}
} catch (Exception ex ) {
ex.printStackTrace();
}
}
static class Task implements Runnable
{
int id;
String[] strings;
int low;
int high;
ConcurrentLinkedQueue queue;
public Task(int id, ConcurrentLinkedQueue queue, String[] strings, int low, int high)
{
System.out.println( "Created Task(" + low +"," + high + ")" );
this.id = id;
this.strings = strings;
this.low = low;
this.high = high;
this.queue = queue;
}
public void run()
{
for (int i=low; i<high; i++) {
queue.add(strings[i]);
}
System.out.println( id + " added - " + queue.size() );
for (int i=low; i<high; i++) {
String s = (String)queue.poll();
}
System.out.println( id + " polled - " + queue.size() );
for (int i=low; i<high; i++) {
queue.add(strings[i]);
}
System.out.println( id + " added - " + queue.size() );
for (int i=low; i<high; i++) {
queue.remove(strings[i]);
}
System.out.println( id + " remove - " + queue.size() );
}
}
}
---------- END SOURCE ----------
- backported by
-
JDK-2186676 ConcurrentLinkedQueue.remove sometimes very slow
-
- Resolved
-
-
JDK-2189209 ConcurrentLinkedQueue.remove sometimes very slow
-
- Resolved
-
-
JDK-2182831 ConcurrentLinkedQueue.remove sometimes very slow
-
- Closed
-