Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6493942

ConcurrentLinkedQueue.remove sometimes very slow

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P4 P4
    • 7
    • 6, 6u17
    • core-libs
    • b70
    • generic, x86
    • generic, windows_xp
    • Verified

        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 ----------

              chegar Chris Hegarty
              ndcosta Nelson Dcosta (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

                Created:
                Updated:
                Resolved:
                Imported:
                Indexed: