JDK-6493942 : ConcurrentLinkedQueue.remove sometimes very slow
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.concurrent
  • Affected Version: 6,6u17
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • OS: generic,windows_xp
  • CPU: generic,x86
  • Submitted: 2006-11-15
  • Updated: 2011-02-16
  • Resolved: 2010-11-30
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 6 JDK 7
6u17-revFixed 7 b70Fixed
Description
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 ----------
Comments
EVALUATION changeset for this fix: http://hg.openjdk.java.net/jdk7/tl/jdk/rev/12e479399ced
07-08-2009
EVALUATION Martin Buchholz writes: This benchmark is bogus. When run serially, the runtime is naturally O(N) because of the nature of the data distribution remove(Object) will always be "lucky" and only need to remove the first element. With concurrency, you may or may not get lucky, but in principle, runtime becomes O(N^2), which no algorithmic improvements will be able to fix. However, I ran a version of this benchmark against changes in progress, and I have observed performance improvement in the 10% - 70% range, so we are going to claim success and declare this bug "fixed".
17-07-2009
EVALUATION Below is a run on gee with bigger timeouts. Mainly because of scheduling tendencies, it is harder to encounter the slow cases for this program on machines with more than 4 CPUs. (It never happened, over a bunch of runs, on T2000.) Doug Lea writes: ------------------------------------------------------------ It is possible to ameliorate this using a variant if the node cleanout algorithm we devised for SynchronousQueue. This can usually splice out removed nodes even in the absence of polls. The "usually" part is because there is one case where you cannot, so need to stash it to clean up after some later remove. I'll look into whether it is worth adding a variant of this here. This won't improve the need for O(N) traversal to locate nodes to remove though, so wouldn't have a dramatic effect in most programs. .... Completed: 2133.801000 seconds, queue size = 56119 ------------------------------------------------------------ I am recasting this as a performance bug, changing the synopsis from "ConcurrentLinkedQueue remove sporadically never returns"
21-11-2006
EVALUATION Doug Lea writes: I think the only problem is that remove(Object) can be VERY VERY slow (as advertised). And this test program will sometimes drive it to its very slowest, which happens when all the polls occur before all the removes. Leading to O(max # elements) traversal per remove, contended among all the threads. Try kicking up the timeout by a factor of ten or so... final int maxSecondsForTermination = 600*10;
16-11-2006
EVALUATION I can reproduce sporadic failures on solaris-sparc I can see no reason why the program should hang. Here's my slightly modified variant of the submitter's program: ---------------------------------------------------- import java.util.concurrent.*; public class Test { public static void main(String arg[]) { new Test().execute(); } public void execute() { final int numElements = 1000000; final int maxSecondsForTermination = 60*10; final String[] strings = new String[numElements]; for (int i = 0; i < strings.length; 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 (Throwable t) { throw new Error(t); } System.out.printf("Starting iteration %d%n", iteration); ConcurrentLinkedQueue<String> queue = new ConcurrentLinkedQueue<String>(); Runnable[] tasks = new Runnable[4]; int size = strings.length/tasks.length; for (int i = 0; i < tasks.length; i++) tasks[i] = new Task(i, queue, strings, i*size, (i+1)*size); runTasks(iteration, maxSecondsForTermination, queue, tasks); } System.out.println( "Done..." ); } public void runTasks(int iteration, int maxSecondsForTermination, ConcurrentLinkedQueue<String> queue, Runnable[] tasks) { ThreadPoolExecutor e = (ThreadPoolExecutor)Executors.newFixedThreadPool(tasks.length); e.prestartAllCoreThreads(); long start = System.currentTimeMillis(); for (Runnable task : tasks) e.execute(task); e.shutdown(); try { if (!e.awaitTermination(maxSecondsForTermination, TimeUnit.SECONDS)) { System.out.printf("Termination took longer than %d seconds%n", maxSecondsForTermination); System.out.printf("queue size = %d%n", queue.size()); } else { double duration = (System.currentTimeMillis() - start) / 1000.0; System.out.printf("Completed: %2f seconds, queue size = %d%n", duration, queue.size()); } } catch (Exception ex) { ex.printStackTrace(); } } static class Task implements Runnable { final int id; final String[] strings; final int low; final int high; final ConcurrentLinkedQueue<String> queue; public Task(int id, ConcurrentLinkedQueue<String> queue, String[] strings, int low, int high) { System.out.printf("Created Task id=%d (%d - %d)%n", id, 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++) 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()); } } } ----------------------------------------------------
15-11-2006