mm23504570 opened a new issue #721: Question About [NOTIFYME]putMessage in lock cost time(ms)=4052 URL: https://github.com/apache/rocketmq/issues/721 ### Question I have used rocketmq in production env. There is some WARN in broker log when user send message to broker. Caused the message to fail to be sent. It looks like it is blocked when it is written to the page cache. Please give me some suggestions to improve this issue. Thank you. In our application scenario, we use much delay message than realtime message. These exceptions occur whenever we consume a lot of delayed messages. Is this related? ### ENV: 1. Tencent cloud linux 8 CPU. 48G MEM. SSD disk I have run broker after run os.sh. I can't set io scheduler to DEADLINE, because machine of cloud not support. default is none 2. broker.conf fileReservedTime = 48 flushDiskType = ASYNC_FLUSH sendMessageThreadPoolNums=48 messageDelayLevel=1s 5s 10s 30s 1m 2m 3m 4m 5m 6m 7m 8m 9m 10m 20m 30m 1h 2h 4h 6h 12h 1d 3h 5h 7h 8h 9h 10h 11h 13h 14h 15h 16h 17h 18h 19h 20h 21h 22h 23h 40m 50m waitTimeMillsInSendQueue=2000 sendThreadPoolQueueCapacity=50000 3. JAVAOPTS is default 4. TPS is less than 2000 ### Some log 2019-01-22 11:03:02 WARN SendMessageThread_19 - [NOTIFYME]putMessage in lock cost time(ms)=4127, bodyLength=410 AppendMessageResult=AppendMessageResult{status=PUT_OK, wroteOffset=3551463997150, wroteBytes=792, msgId='0A01003100002A9F0000033AE3BFFEDE', storeTimestamp=1548126178835, logicsOffset=422117414, pagecacheRT=4127, msgNum=1} 2019-01-22 11:03:02 WARN SendMessageThread_22 - putMessage not in lock eclipse time(ms)=4034, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_25 - putMessage not in lock eclipse time(ms)=4128, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_44 - putMessage not in lock eclipse time(ms)=4061, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_36 - putMessage not in lock eclipse time(ms)=4057, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_40 - putMessage not in lock eclipse time(ms)=4103, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_21 - putMessage not in lock eclipse time(ms)=4127, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_20 - putMessage not in lock eclipse time(ms)=4081, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_16 - putMessage not in lock eclipse time(ms)=4127, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_30 - putMessage not in lock eclipse time(ms)=4093, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_35 - putMessage not in lock eclipse time(ms)=4067, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_13 - putMessage not in lock eclipse time(ms)=4136, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_37 - putMessage not in lock eclipse time(ms)=3939, bodyLength=9 2019-01-22 11:03:02 WARN SendMessageThread_26 - putMessage not in lock eclipse time(ms)=4034, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_42 - putMessage not in lock eclipse time(ms)=4082, bodyLength=397 2019-01-22 11:03:02 WARN SendMessageThread_39 - putMessage not in lock eclipse time(ms)=4127, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_46 - putMessage not in lock eclipse time(ms)=4012, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_14 - putMessage not in lock eclipse time(ms)=4056, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_6 - putMessage not in lock eclipse time(ms)=4001, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_11 - putMessage not in lock eclipse time(ms)=4138, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_32 - putMessage not in lock eclipse time(ms)=4092, bodyLength=367 2019-01-22 11:03:02 WARN SendMessageThread_4 - putMessage not in lock eclipse time(ms)=4123, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_29 - putMessage not in lock eclipse time(ms)=4138, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_1 - putMessage not in lock eclipse time(ms)=4102, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_10 - putMessage not in lock eclipse time(ms)=4087, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_12 - putMessage not in lock eclipse time(ms)=4080, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_3 - putMessage not in lock eclipse time(ms)=4081, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_33 - putMessage not in lock eclipse time(ms)=4103, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_27 - putMessage not in lock eclipse time(ms)=3980, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_43 - putMessage not in lock eclipse time(ms)=3951, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_41 - putMessage not in lock eclipse time(ms)=4046, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_38 - putMessage not in lock eclipse time(ms)=3991, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_18 - putMessage not in lock eclipse time(ms)=4083, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_2 - putMessage not in lock eclipse time(ms)=4122, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_7 - putMessage not in lock eclipse time(ms)=4120, bodyLength=367 2019-01-22 11:03:02 WARN SendMessageThread_15 - putMessage not in lock eclipse time(ms)=3980, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_34 - putMessage not in lock eclipse time(ms)=4122, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_8 - putMessage not in lock eclipse time(ms)=4077, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_28 - putMessage not in lock eclipse time(ms)=4074, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_17 - putMessage not in lock eclipse time(ms)=4024, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_31 - putMessage not in lock eclipse time(ms)=3962, bodyLength=410 2019-01-22 11:03:02 WARN ScheduleMessageTimerThread - putMessage not in lock eclipse time(ms)=4128, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_47 - putMessage not in lock eclipse time(ms)=4127, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_48 - putMessage not in lock eclipse time(ms)=4083, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_45 - putMessage not in lock eclipse time(ms)=4113, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_24 - putMessage not in lock eclipse time(ms)=3951, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_19 - putMessage not in lock eclipse time(ms)=4128, bodyLength=410 2019-01-22 11:03:02 WARN SendMessageThread_9 - putMessage not in lock eclipse time(ms)=3969, bodyLength=411 2019-01-22 11:03:02 WARN SendMessageThread_5 - putMessage not in lock eclipse time(ms)=4093, bodyLength=422 2019-01-22 11:03:02 WARN SendMessageThread_23 - putMessage not in lock eclipse time(ms)=3928, bodyLength=8 2019-01-25 12:24:07 WARN SendMessageThread_21 - putMessage not in lock eclipse time(ms)=537, bodyLength=206 2019-01-25 12:24:07 WARN SendMessageThread_5 - putMessage not in lock eclipse time(ms)=509, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_28 - putMessage not in lock eclipse time(ms)=656, bodyLength=221 2019-01-25 12:24:07 WARN SendMessageThread_35 - putMessage not in lock eclipse time(ms)=602, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_10 - putMessage not in lock eclipse time(ms)=685, bodyLength=438 2019-01-25 12:24:07 WARN SendMessageThread_14 - putMessage not in lock eclipse time(ms)=597, bodyLength=523 2019-01-25 12:24:07 WARN SendMessageThread_44 - putMessage not in lock eclipse time(ms)=719, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_16 - putMessage not in lock eclipse time(ms)=509, bodyLength=200 2019-01-25 12:24:07 WARN SendMessageThread_13 - putMessage not in lock eclipse time(ms)=603, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_9 - putMessage not in lock eclipse time(ms)=587, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_18 - putMessage not in lock eclipse time(ms)=521, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_23 - putMessage not in lock eclipse time(ms)=507, bodyLength=49 2019-01-25 12:24:07 WARN SendMessageThread_31 - putMessage not in lock eclipse time(ms)=546, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_32 - putMessage not in lock eclipse time(ms)=627, bodyLength=115 2019-01-25 12:24:07 WARN ScheduleMessageTimerThread - putMessage not in lock eclipse time(ms)=722, bodyLength=273 2019-01-25 12:24:07 WARN SendMessageThread_12 - putMessage not in lock eclipse time(ms)=714, bodyLength=566 2019-01-25 12:24:07 WARN SendMessageThread_41 - putMessage not in lock eclipse time(ms)=732, bodyLength=338 2019-01-25 12:24:07 WARN SendMessageThread_1 - putMessage not in lock eclipse time(ms)=563, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_15 - putMessage not in lock eclipse time(ms)=707, bodyLength=201 2019-01-25 12:24:07 WARN SendMessageThread_40 - putMessage not in lock eclipse time(ms)=563, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_2 - putMessage not in lock eclipse time(ms)=603, bodyLength=238 2019-01-25 12:24:07 WARN SendMessageThread_17 - putMessage not in lock eclipse time(ms)=530, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_8 - putMessage not in lock eclipse time(ms)=736, bodyLength=408 2019-01-25 12:24:07 WARN SendMessageThread_11 - putMessage not in lock eclipse time(ms)=533, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_20 - putMessage not in lock eclipse time(ms)=688, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_29 - putMessage not in lock eclipse time(ms)=741, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_3 - putMessage not in lock eclipse time(ms)=508, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_7 - putMessage not in lock eclipse time(ms)=707, bodyLength=74 2019-01-25 12:24:07 WARN SendMessageThread_46 - putMessage not in lock eclipse time(ms)=688, bodyLength=259 2019-01-25 12:24:07 WARN SendMessageThread_30 - putMessage not in lock eclipse time(ms)=680, bodyLength=229 2019-01-25 12:24:07 WARN SendMessageThread_36 - putMessage not in lock eclipse time(ms)=659, bodyLength=228 2019-01-25 12:24:07 WARN SendMessageThread_34 - putMessage not in lock eclipse time(ms)=551, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_39 - putMessage not in lock eclipse time(ms)=664, bodyLength=100 2019-01-25 12:24:07 WARN SendMessageThread_4 - putMessage not in lock eclipse time(ms)=749, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_33 - [NOTIFYME]putMessage in lock cost time(ms)=723, bodyLength=99 AppendMessageResult=AppendMessageResult{status=PUT_OK, wroteOffset=3637677915929, wroteBytes=398, msgId='0A01003100002A9F0000034EF67FFF19', storeTimestamp=1548390246329, logicsOffset=3777623, pagecacheRT=723, msgNum=1} 2019-01-25 12:24:07 WARN SendMessageThread_33 - putMessage not in lock eclipse time(ms)=768, bodyLength=99 2019-01-25 12:24:07 WARN SendMessageThread_42 - putMessage not in lock eclipse time(ms)=645, bodyLength=110 2019-01-25 12:24:07 WARN SendMessageThread_6 - putMessage not in lock eclipse time(ms)=580, bodyLength=200 2019-01-25 12:24:07 WARN SendMessageThread_43 - putMessage not in lock eclipse time(ms)=520, bodyLength=74 2019-01-25 12:24:07 WARN SendMessageThread_37 - putMessage not in lock eclipse time(ms)=617, bodyLength=74 2019-01-25 12:24:07 WARN SendMessageThread_27 - putMessage not in lock eclipse time(ms)=685, bodyLength=100 2019-01-25 12:24:07 WARN SendMessageThread_47 - putMessage not in lock eclipse time(ms)=627, bodyLength=559 2019-01-25 12:24:07 WARN SendMessageThread_25 - putMessage not in lock eclipse time(ms)=718, bodyLength=279 2019-01-25 12:24:07 WARN SendMessageThread_45 - putMessage not in lock eclipse time(ms)=559, bodyLength=425 2019-01-25 12:24:07 WARN SendMessageThread_26 - putMessage not in lock eclipse time(ms)=692, bodyLength=115 2019-01-25 12:24:07 WARN SendMessageThread_22 - putMessage not in lock eclipse time(ms)=602, bodyLength=446 Jan 25 sar -B 09时00分01秒 pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff 09时10分01秒 53.90 2150.23 603.07 0.05 6046.29 108.76 0.00 104.54 96.12 09时20分01秒 68.76 2037.86 597.67 0.06 6079.41 135.21 0.00 127.00 93.93 09时30分01秒 41.85 1953.13 593.96 0.04 5986.48 41.96 0.00 38.02 90.60 09时40分01秒 218.06 1910.26 591.13 0.14 6039.40 176.76 0.00 162.66 92.02 09时50分01秒 259.03 2130.62 597.69 0.14 6020.30 174.67 0.00 153.54 87.90 10时00分01秒 12.83 1944.46 587.39 0.02 6002.22 75.59 0.00 67.29 89.01 10时10分01秒 334.58 2678.21 651.55 0.17 6597.55 198.01 0.00 184.85 93.36 10时20分01秒 65.39 2727.90 649.05 0.05 6533.37 143.67 0.00 133.15 92.67 10时30分01秒 71.57 2843.67 649.52 0.05 6519.89 148.09 0.00 131.89 89.07 10时40分01秒 598.96 2456.35 618.90 0.27 6377.77 271.93 0.00 238.88 87.85 10时50分01秒 681.50 3493.50 708.71 0.32 7013.90 328.37 0.00 286.70 87.31 11时00分01秒 2133.78 5041.79 1115.00 1.54 10959.66 1752.14 0.00 1504.10 85.84 11时10分01秒 710.04 4035.66 780.01 0.29 11366.08 687.29 0.00 423.10 61.56 11时20分01秒 222.00 1665.62 572.50 0.11 10287.25 158.53 0.00 99.28 62.63 11时30分01秒 189.29 1588.65 571.60 0.10 23648.61 146.99 0.00 95.86 65.22 11时40分01秒 223.05 1519.33 570.70 0.15 6894.66 293.27 0.00 115.52 39.39 11时50分01秒 235.13 1918.83 571.58 0.16 6124.60 459.42 0.00 159.91 34.81 12时00分01秒 199.34 1768.49 588.22 0.15 8396.45 153.84 0.00 72.71 47.26 12时10分01秒 1004.09 1763.49 693.69 0.46 8764.61 930.06 4.40 377.07 40.35 12时20分01秒 961.36 1533.94 580.84 0.43 8560.14 780.52 0.00 321.29 41.16 12时30分01秒 1014.18 1687.05 576.44 0.49 8590.14 457.40 1.61 270.16 58.86 12时40分01秒 993.98 1601.02 571.71 0.46 8627.73 474.87 0.00 289.02 60.86 12时50分01秒 636.37 1550.81 565.83 0.34 8576.74 243.91 0.00 239.92 98.37 13时00分01秒 256.55 1513.39 564.31 0.21 8460.28 154.36 0.00 149.51 96.85 13时10分01秒 523.77 3249.68 716.50 0.28 11102.90 285.32 0.00 278.41 97.58 13时20分01秒 750.04 3301.08 726.68 0.35 11199.65 308.59 0.00 303.10 98.22 13时30分01秒 744.75 3240.18 678.40 0.36 10701.32 418.28 0.00 299.91 71.70 13时40分01秒 969.07 2451.22 629.35 0.44 10050.09 487.96 0.00 357.73 73.31 13时50分01秒 592.18 2429.16 629.88 0.31 9914.20 442.84 0.00 290.90 65.69 14时00分01秒 448.55 1771.07 585.40 0.27 8824.74 139.92 0.00 118.98 85.03 14时10分01秒 657.93 1832.27 634.43 0.39 8736.66 295.38 0.00 248.61 84.17 平均时间: 907.71 1684.08 619.83 0.41 6832.66 409.30 0.10 316.49 77.31  
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
