You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@rocketmq.apache.org by GitBox <gi...@apache.org> on 2019/01/25 08:11:21 UTC
[GitHub] mm23504570 opened a new issue #721: Question About
[NOTIFYME]putMessage in lock cost time(ms)=4052
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:
users@infra.apache.org
With regards,
Apache Git Services