This article is participating in the Java Theme Month – Java Debug Notes Event, see the event link for details
1. Background
A very frequently invoked method with synchronized crashes the program
Simulating the occurrence of accidents
-
Create a thread pool to simulate multi-user access
ThreadPoolExecutor ThreadPoolExecutor = new ThreadPoolExecutor (10,10,0 L, TimeUnit MICROSECONDS, new ArrayBlockingQueue<>(10)); for (int i = 0; i <1000; i++) { threadPoolExecutor.execute(()->{ testSync(); }); } public static synchronized void testSync(){try {system.out.println ("Hi thread pool "); Thread.sleep(30000); } catch (InterruptedException e) { e.printStackTrace(); }}Copy the code
The following error occurs
Exception in thread "main" java.util.concurrent.RejectedExecutionException: Task com.sunisco.collect.ugqd.web.pages.Test$$Lambda$1/1642360923@6aa8ceb6 rejected from java.util.concurrent.ThreadPoolExecutor@2530c12[Running, pool size = 10, active threads = 10, queued tasks = 10, completed tasks = 0] at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) at com.sunisco.collect.ugqd.web.pages.Test.main(Test.java:24) Copy the code
This is because the number of runs is greater than the number of queues, and tests continue after modification
ThreadPoolExecutor ThreadPoolExecutor = new ThreadPoolExecutor (10,10,0 L, TimeUnit MICROSECONDS, new ArrayBlockingQueue<>(100)); for (int i = 0; i <100; i++) { threadPoolExecutor.execute(()->{ testSync(); }); } public static synchronized void testSync(){try {system.out.println ("Hi thread pool "); Thread.sleep(30000); } catch (InterruptedException e) { e.printStackTrace(); }}Copy the code
The output is as follows
-
Through JPS to view all the system Java process PID, find our program PID 12308
C:\Users\Administrator>jps 11088 RemoteMavenServer 8352 Test 12308 Test 10632 Launcher 9384 Launcher 11100 6572 Jps 9180 TestCopy the code
-
Run the jStack 12308 command to view information about the threads in the process
C:\Users\Administrator>jstack 12308 2021-05-13 09:34:53 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.141-b15 mixed mode): "DestroyJavaVM" #21 prio=5 os_prio=0 tid=0x000000001ec4f800 nid=0x27bc waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "pool-1-thread-10" #20 prio=5 os_prio=0 tid=0x000000001ec4e000 nid=0x1650 waiting for monitor entry [0x000000001ff8f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.sunisco.collect.ugqd.web.pages.Test.getg(Test.java:55) - waiting to lock <0x000000076b740d80> (a java.lang.Class for com.sunisco.collect.ugqd.web.pages.Test) at com.sunisco.collect.ugqd.web.pages.Test.lambda$main$0(Test.java:27) at com.sunisco.collect.ugqd.web.pages.Test$$Lambda$1/1642360923.run(Unknown Source) 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:748) "pool-1-thread-9" #19 prio=5 os_prio=0 tid=0x000000001ec4a000 nid=0x2a88 waiting on condition [0x000000001fe8f000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at com.sunisco.collect.ugqd.web.pages.Test.getg(Test.java:56) - locked <0x000000076b740d80> (a java.lang.Class for com.sunisco.collect.ugqd.web.pages.Test) at com.sunisco.collect.ugqd.web.pages.Test.lambda$main$0(Test.java:27) at com.sunisco.collect.ugqd.web.pages.Test$$Lambda$1/1642360923.run(Unknown Source) 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:748) "pool-1-thread-2" #12 prio=5 os_prio=0 tid=0x000000001ea78000 nid=0x1250 waiting for monitor entry [0x000000001f78f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.sunisco.collect.ugqd.web.pages.Test.getg(Test.java:55) - waiting to lock <0x000000076b740d80> (a java.lang.Class for com.sunisco.collect.ugqd.web.pages.Test) at com.sunisco.collect.ugqd.web.pages.Test.lambda$main$0(Test.java:27) at com.sunisco.collect.ugqd.web.pages.Test$$Lambda$1/1642360923.run(Unknown Source) 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:748) "pool-1-thread-1" #11 prio=5 os_prio=0 tid=0x000000001ec11800 nid=0xa38 waiting for monitor entry [0x000000001f68f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.sunisco.collect.ugqd.web.pages.Test.getg(Test.java:55) - waiting to lock <0x000000076b740d80> (a java.lang.Class for com.sunisco.collect.ugqd.web.pages.Test) at com.sunisco.collect.ugqd.web.pages.Test.lambda$main$0(Test.java:27) at com.sunisco.collect.ugqd.web.pages.Test$$Lambda$1/1642360923.run(Unknown Source) 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:748) "Service Thread" #10 daemon prio=9 os_prio=0 tid=0x000000001e93c000 nid=0x226c runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C1 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x000000001e8c9800 nid=0x21d8 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Monitor Ctrl-Break" #6 daemon prio=5 os_prio=0 tid=0x000000001e84b000 nid=0x1c4c runnable [0x000000001f08e000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178) - locked <0x000000076b82f3e0> (a java.io.InputStreamReader) at java.io.InputStreamReader.read(InputStreamReader.java:184) at java.io.BufferedReader.fill(BufferedReader.java:161) at java.io.BufferedReader.readLine(BufferedReader.java:324) - locked <0x000000076b82f3e0> (a java.io.InputStreamReader) at java.io.BufferedReader.readLine(BufferedReader.java:389) at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64) "Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000001cdf9800 nid=0x35ec waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x000000001cde4800 nid=0x34e8 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001cdbf000 nid=0x54c in Object.wait() [0x000000001e12f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x000000076b188ec8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143) - locked <0x000000076b188ec8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209) "Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000003687000 nid=0x3318 in Object.wait() [0x000000001e02e000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x000000076b186b68> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) - locked <0x000000076b186b68> (a java.lang.ref.Reference$Lock) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "VM Thread" os_prio=2 tid=0x000000001cd97800 nid=0x2d1c runnable "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00000000035ad000 nid=0x1efc runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00000000035ae800 nid=0xa50 runnable "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00000000035b1000 nid=0x1bac runnable "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00000000035b3000 nid=0x2d50 runnable "VM Periodic Task Thread" os_prio=2 tid=0x000000001ea1a800 nid=0x27f4 waiting on condition JNI global references: 335 Copy the code
The jStack log shows that there are many block-state threads, and the production problem is that there are too many block-state threads, which cause the program to crash.
Three conclusion
Locking is an effective way to handle data inconsistencies caused by concurrency, but it can have a significant impact on performance if not used properly, so be careful before using it.