You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Duo Zhang (JIRA)" <ji...@apache.org> on 2018/09/12 14:19:00 UTC
[jira] [Commented] (HBASE-21188) Print heap and gc informations in
our junit ResourceChecker
[ https://issues.apache.org/jira/browse/HBASE-21188?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16612203#comment-16612203 ]
Duo Zhang commented on HBASE-21188:
-----------------------------------
The output is like this
{noformat}
2018-09-12 22:09:20,396 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testTailMap Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=104, ProcessCount=330, AvailableMemoryMB=1015, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=21, GCCount=0, GCTimeSecond=0
2018-09-12 22:09:24,759 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testTailMap Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 104) - SystemLoadAverage LEAK? -, ProcessCount=330 (was 330), AvailableMemoryMB=973 (was 1015), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=38 (was 21) - UsedHeapMemoryMB LEAK? -, GCCount=4 (was 0) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:24,772 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testLastEntry Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=973, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=38, GCCount=4, GCTimeSecond=0
2018-09-12 22:09:24,842 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testLastEntry Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=926 (was 973), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=44 (was 38) - UsedHeapMemoryMB LEAK? -, GCCount=6 (was 4) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:24,863 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testFloorKey Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=926, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=44, GCCount=6, GCTimeSecond=0
2018-09-12 22:09:24,939 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testFloorKey Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=834 (was 926), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=48 (was 44) - UsedHeapMemoryMB LEAK? -, GCCount=7 (was 6) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:24,950 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testPut Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=833, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=48, GCCount=7, GCTimeSecond=0
2018-09-12 22:09:24,995 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testPut Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=832 (was 833), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=55 (was 48) - UsedHeapMemoryMB LEAK? -, GCCount=8 (was 7) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,009 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testFindOnEmpty Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=832, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=57, GCCount=8, GCTimeSecond=0
2018-09-12 22:09:25,074 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testFindOnEmpty Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=786 (was 832), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=245 (was 57) - UsedHeapMemoryMB LEAK? -, GCCount=8 (was 8), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,088 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testKeys Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=786, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=245, GCCount=8, GCTimeSecond=0
2018-09-12 22:09:25,219 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testKeys Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=645 (was 786), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=251 (was 245) - UsedHeapMemoryMB LEAK? -, GCCount=9 (was 8) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,230 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testSize Thread=8, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=645, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=251, GCCount=9, GCTimeSecond=0
2018-09-12 22:09:25,279 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testSize Thread=8 (was 8), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=643 (was 645), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=67 (was 251), GCCount=10 (was 9) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,291 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testLowerKey Thread=9, OpenFileDescriptor=88, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=643, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=67, GCCount=10, GCTimeSecond=0
2018-09-12 22:09:25,330 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testLowerKey Thread=9 (was 9), OpenFileDescriptor=85 (was 88), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=643 (was 643), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=262 (was 67) - UsedHeapMemoryMB LEAK? -, GCCount=10 (was 10), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,343 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testTailMapExclusive Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=643, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=262, GCCount=10, GCTimeSecond=0
2018-09-12 22:09:25,403 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testTailMapExclusive Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=119 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=574 (was 643), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=456 (was 262) - UsedHeapMemoryMB LEAK? -, GCCount=10 (was 10), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,414 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testFirstEntry Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=119, ProcessCount=330, AvailableMemoryMB=574, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=456, GCCount=10, GCTimeSecond=0
2018-09-12 22:09:25,545 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testFirstEntry Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 119), ProcessCount=330 (was 330), AvailableMemoryMB=415 (was 574), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=39 (was 456), GCCount=11 (was 10) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,557 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testLastKey Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=415, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=39, GCCount=11, GCTimeSecond=0
2018-09-12 22:09:25,595 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testLastKey Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=415 (was 415), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=232 (was 39) - UsedHeapMemoryMB LEAK? -, GCCount=11 (was 11), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,605 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testHigherKey Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=415, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=232, GCCount=11, GCTimeSecond=0
2018-09-12 22:09:25,643 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testHigherKey Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=415 (was 415), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=426 (was 232) - UsedHeapMemoryMB LEAK? -, GCCount=11 (was 11), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,654 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testTailMapInclusive Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=415, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=427, GCCount=11, GCTimeSecond=0
2018-09-12 22:09:25,700 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testTailMapInclusive Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=413 (was 415), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=21 (was 427), GCCount=12 (was 11) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,716 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testFirstKey Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=413, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=21, GCCount=12, GCTimeSecond=0
2018-09-12 22:09:25,757 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testFirstKey Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=413 (was 413), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=205 (was 21) - UsedHeapMemoryMB LEAK? -, GCCount=12 (was 12), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,769 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testReplace1 Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=413, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=205, GCCount=12, GCTimeSecond=0
2018-09-12 22:09:25,968 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testReplace1 Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=245 (was 413), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=794 (was 205) - UsedHeapMemoryMB LEAK? -, GCCount=12 (was 12), GCTimeSecond=0 (was 0)
2018-09-12 22:09:25,980 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testReplace Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=245, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=794, GCCount=12, GCTimeSecond=0
2018-09-12 22:09:26,205 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testReplace Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=162 (was 245), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=445 (was 794), GCCount=13 (was 12) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:26,218 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testMultiAdd Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=162, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=445, GCCount=13, GCTimeSecond=0
2018-09-12 22:09:27,892 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testMultiAdd Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=156 (was 162), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=55 (was 445), GCCount=21 (was 13) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:27,904 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testIsEmpty Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=156, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=56, GCCount=21, GCTimeSecond=0
2018-09-12 22:09:27,952 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testIsEmpty Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=156 (was 156), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=235 (was 56) - UsedHeapMemoryMB LEAK? -, GCCount=21 (was 21), GCTimeSecond=0 (was 0)
2018-09-12 22:09:27,965 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testRemove Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=156, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=235, GCCount=21, GCTimeSecond=0
2018-09-12 22:09:28,042 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testRemove Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=118 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=156 (was 156), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=624 (was 235) - UsedHeapMemoryMB LEAK? -, GCCount=21 (was 21), GCTimeSecond=0 (was 0)
2018-09-12 22:09:28,054 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testValues Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=118, ProcessCount=330, AvailableMemoryMB=156, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=624, GCCount=21, GCTimeSecond=0
2018-09-12 22:09:30,688 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testValues Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=115 (was 118), ProcessCount=330 (was 330), AvailableMemoryMB=155 (was 156), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=830 (was 624) - UsedHeapMemoryMB LEAK? -, GCCount=21 (was 21), GCTimeSecond=0 (was 0)
2018-09-12 22:09:30,699 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testCeilingKey Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=115, ProcessCount=330, AvailableMemoryMB=155, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=839, GCCount=21, GCTimeSecond=0
2018-09-12 22:09:30,740 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testCeilingKey Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=115 (was 115), ProcessCount=330 (was 330), AvailableMemoryMB=155 (was 155), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=108 (was 839), GCCount=22 (was 21) - GCCount LEAK? -, GCTimeSecond=0 (was 0)
2018-09-12 22:09:30,752 INFO [Time-limited test] hbase.ResourceChecker(148): before: types.TestCopyOnWriteMaps#testFloorEntry Thread=9, OpenFileDescriptor=85, MaxFileDescriptor=4096, SystemLoadAverage=115, ProcessCount=330, AvailableMemoryMB=155, MaxHeapMemoryMB=2489, UsedHeapMemoryMB=114, GCCount=22, GCTimeSecond=0
2018-09-12 22:09:30,803 INFO [Time-limited test] hbase.ResourceChecker(172): after: types.TestCopyOnWriteMaps#testFloorEntry Thread=9 (was 9), OpenFileDescriptor=85 (was 85), MaxFileDescriptor=4096 (was 4096), SystemLoadAverage=115 (was 115), ProcessCount=330 (was 330), AvailableMemoryMB=155 (was 155), MaxHeapMemoryMB=2489 (was 2489), UsedHeapMemoryMB=314 (was 114) - UsedHeapMemoryMB LEAK? -, GCCount=22 (was 22), GCTimeSecond=0 (was 0)
{noformat}
> Print heap and gc informations in our junit ResourceChecker
> -----------------------------------------------------------
>
> Key: HBASE-21188
> URL: https://issues.apache.org/jira/browse/HBASE-21188
> Project: HBase
> Issue Type: Sub-task
> Components: test
> Reporter: Duo Zhang
> Assignee: Duo Zhang
> Priority: Major
> Fix For: 3.0.0, 2.2.0
>
> Attachments: HBASE-21188.patch
>
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)