Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 3AA6A200BEF for ; Wed, 4 Jan 2017 14:19:06 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 396CA160B3A; Wed, 4 Jan 2017 13:19:06 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 33F24160B39 for ; Wed, 4 Jan 2017 14:19:05 +0100 (CET) Received: (qmail 18191 invoked by uid 500); 4 Jan 2017 13:18:59 -0000 Mailing-List: contact dev-help@phoenix.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@phoenix.apache.org Delivered-To: mailing list dev@phoenix.apache.org Received: (qmail 18113 invoked by uid 99); 4 Jan 2017 13:18:59 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 04 Jan 2017 13:18:59 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id 013B62C2A66 for ; Wed, 4 Jan 2017 13:18:59 +0000 (UTC) Date: Wed, 4 Jan 2017 13:18:59 +0000 (UTC) From: "Yeonseop Kim (JIRA)" To: dev@phoenix.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (PHOENIX-3553) Zookeeper connection should be closed immediately after DefaultStatisticsCollector's collecting stats done MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Wed, 04 Jan 2017 13:19:06 -0000 [ https://issues.apache.org/jira/browse/PHOENIX-3553?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15798247#comment-15798247 ] Yeonseop Kim edited comment on PHOENIX-3553 at 1/4/17 1:18 PM: --------------------------------------------------------------- ScanType.COMPACT_DROP_DELETES is determined in DefaultCompactor and CompactionRequest class {code:title=DefaultCompactor.java|borderStyle=solid} public List compact(final CompactionRequest request, CompactionThroughputController throughputController, User user) throws IOException { ... ScanType scanType = request.isAllFiles() ? ScanType.COMPACT_DROP_DELETES : ScanType.COMPACT_RETAIN_DELETES; ... {code} {code:title=CompactionRequest.java|borderStyle=solid} public boolean isAllFiles() { return this.isMajor == DisplayCompactionType.MAJOR || this.isMajor == DisplayCompactionType.ALL_FILES; } public boolean isMajor() { return this.isMajor == DisplayCompactionType.MAJOR; } {code} Following is real HBase log (v1.1.8) from my site. You can find that during compaction, 2 zookeeper connections are established, but only one connection is closed. (sessionid=0x259160941a6fa5d,0x259160941a6fa5e) Last line of log tell us that this compaction is DisplayCompactionType.ALL_FILES type compaction, not DisplayCompactionType.MAJOR. There should be a word "major" appeared in the last line for the compaction type to be DisplayCompactionType.MAJOR. {noformat} 2016-12-23 16:48:31,112 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] regionserver.HStore: Starting compaction of 6 file(s) in L#0 of TEST.TEST_TABLE,\x0DTCCLN78\x00K4571038A\x00MA_RES_RMV_INTRA_CHUCK\x0009\x00TCCLN78,1482479246551.044fb02eb5f873b692730b2dcbe76e13. into tmpdir=hdfs://ichbig/hbase/data/default/TEST.TEST_TABLE/044fb02eb5f873b692730b2dcbe76e13/.tmp, totalSize=25.8 M 2016-12-23 16:48:31,195 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7a261ee connecting to ZooKeeper ensemble=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 2016-12-23 16:48:31,195 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.ZooKeeper: Initiating client connection, connectString=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 sessionTimeout=90000 watcher=hconnection-0x7a261ee0x0, quorum=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181, baseZNode=/hbase 2016-12-23 16:48:31,197 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Opening socket connection to server ichbig-01-005/172.16.252.25:2181. Will not attempt to authenticate using SASL (unknown error) 2016-12-23 16:48:31,197 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Socket connection established to ichbig-01-005/172.16.252.25:2181, initiating session 2016-12-23 16:48:31,204 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Session establishment complete on server ichbig-01-005/172.16.252.25:2181, sessionid = 0x259160941a6fa5d, negotiated timeout = 90000 2016-12-23 16:48:31,207 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7cdbb8b2 connecting to ZooKeeper ensemble=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 2016-12-23 16:48:31,207 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.ZooKeeper: Initiating client connection, connectString=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 sessionTimeout=90000 watcher=hconnection-0x7cdbb8b20x0, quorum=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181, baseZNode=/hbase 2016-12-23 16:48:31,208 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Opening socket connection to server ichbig-01-005/172.16.252.25:2181. Will not attempt to authenticate using SASL (unknown error) 2016-12-23 16:48:31,208 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Socket connection established to ichbig-01-005/172.16.252.25:2181, initiating session 2016-12-23 16:48:31,215 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Session establishment complete on server ichbig-01-005/172.16.252.25:2181, sessionid = 0x259160941a6fa5e, negotiated timeout = 90000 2016-12-23 16:48:31,223 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] hfile.CacheConfig: blockCache=org.apache.hadoop.hbase.io.hfile.CombinedBlockCache@7a2e3a98, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false 2016-12-23 16:48:35,542 INFO [phoenix-update-statistics-0] client.ConnectionManager$HConnectionImplementation: Closing zookeeper sessionid=0x259160941a6fa5d 2016-12-23 16:48:35,549 INFO [phoenix-update-statistics-0] zookeeper.ZooKeeper: Session: 0x259160941a6fa5d closed 2016-12-23 16:48:35,549 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-EventThread] zookeeper.ClientCnxn: EventThread shut down 2016-12-23 16:48:35,900 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] regionserver.HStore: Completed compaction of 6 (all) file(s) in L#0 of TEST.TEST_TABLE,\x0DTCCLN78\x00K4571038A\x00MA_RES_RMV_INTRA_CHUCK\x0009\x00TCCLN78,1482479246551.044fb02eb5f873b692730b2dcbe76e13. into 2b6043fc7d584afabfdd74f7b4e16c8d(size=16.8 M), total size for store is 16.8 M. This selection was in queue for 0sec, and took 4sec to execute. {noformat} was (Author: nilkis): ScanType.COMPACT_DROP_DELETES is determined in DefaultCompactor and CompactionRequest class {code:title=DefaultCompactor.java|borderStyle=solid} public List compact(final CompactionRequest request, CompactionThroughputController throughputController, User user) throws IOException { ... ScanType scanType = request.isAllFiles() ? ScanType.COMPACT_DROP_DELETES : ScanType.COMPACT_RETAIN_DELETES; ... {code} {code:title=CompactionRequest.java|borderStyle=solid} public boolean isAllFiles() { return this.isMajor == DisplayCompactionType.MAJOR || this.isMajor == DisplayCompactionType.ALL_FILES; } public boolean isMajor() { return this.isMajor == DisplayCompactionType.MAJOR; } {code} Following is real HBase log (v1.1.8) from my site. You can find that during compaction, 2 zookeeper connections are established, but only one connection is closed. (sessionid=0x259160941a6fa5d,0x259160941a6fa5e) Last line of log tell us that this compaction is DisplayCompactionType.ALL_FILES type compaction, not DisplayCompactionType.MAJOR. There should be a word "major" appeared in the last line for the compaction type to be DisplayCompactionType.MAJOR. {noformat} 2016-12-23 16:48:31,112 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] regionserver.HStore: Starting compaction of 6 file(s) in L#0 of TEST.TEST_TABLE,\x0DTCCLN78\x00K4571038A\x00MA_RES_RMV_INTRA_CHUCK\x0009\x00TCCLN78,1482479246551.044fb02eb5f873b692730b2dcbe76e13. into tmpdir=hdfs://ichbig/hbase/data/default/TEST.TEST_TABLE/044fb02eb5f873b692730b2dcbe76e13/.tmp, totalSize=25.8 M 2016-12-23 16:48:31,195 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7a261ee connecting to ZooKeeper ensemble=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 2016-12-23 16:48:31,195 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.ZooKeeper: Initiating client connection, connectString=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 sessionTimeout=90000 watcher=hconnection-0x7a261ee0x0, quorum=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181, baseZNode=/hbase 2016-12-23 16:48:31,197 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Opening socket connection to server ichbig-01-005/172.16.252.25:2181. Will not attempt to authenticate using SASL (unknown error) 2016-12-23 16:48:31,197 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Socket connection established to ichbig-01-005/172.16.252.25:2181, initiating session 2016-12-23 16:48:31,204 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Session establishment complete on server ichbig-01-005/172.16.252.25:2181, sessionid = 0x259160941a6fa5d, negotiated timeout = 90000 2016-12-23 16:48:31,207 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7cdbb8b2 connecting to ZooKeeper ensemble=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 2016-12-23 16:48:31,207 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] zookeeper.ZooKeeper: Initiating client connection, connectString=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181 sessionTimeout=90000 watcher=hconnection-0x7cdbb8b20x0, quorum=ichbig-01-004:2181,ichbig-01-005:2181,ichbig-02-005:2181,ichbig-01-006:2181,ichbig-02-006:2181, baseZNode=/hbase 2016-12-23 16:48:31,208 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Opening socket connection to server ichbig-01-005/172.16.252.25:2181. Will not attempt to authenticate using SASL (unknown error) 2016-12-23 16:48:31,208 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Socket connection established to ichbig-01-005/172.16.252.25:2181, initiating session 2016-12-23 16:48:31,215 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-SendThread(ichbig-01-005:2181)] zookeeper.ClientCnxn: Session establishment complete on server ichbig-01-005/172.16.252.25:2181, sessionid = 0x259160941a6fa5e, negotiated timeout = 90000 2016-12-23 16:48:31,223 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] hfile.CacheConfig: blockCache=org.apache.hadoop.hbase.io.hfile.CombinedBlockCache@7a2e3a98, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false 2016-12-23 16:48:35,542 INFO [phoenix-update-statistics-0] client.ConnectionManager$HConnectionImplementation: Closing zookeeper sessionid=0x259160941a6fa5d 2016-12-23 16:48:35,549 INFO [phoenix-update-statistics-0] zookeeper.ZooKeeper: Session: 0x259160941a6fa5d closed 2016-12-23 16:48:35,549 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607-EventThread] zookeeper.ClientCnxn: EventThread shut down 2016-12-23 16:48:35,900 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] regionserver.HStore: Completed compaction of 6 (all) file(s) in L#0 of TEST.TEST_TABLE,\x0DTCCLN78\x00K4571038A\x00MA_RES_RMV_INTRA_CHUCK\x0009\x00TCCLN78,1482479246551.044fb02eb5f873b692730b2dcbe76e13. into 2b6043fc7d584afabfdd74f7b4e16c8d(size=16.8 M), total size for store is 16.8 M. This selection was in queue for 0sec, and took 4sec to execute. 2016-12-23 16:48:35,901 INFO [regionserver/myhost/172.16.252.78:16020-shortCompactions-1482479243607] regionserver.CompactSplitThread: Completed compaction: Request = regionName=TEST.TEST_TABLE,\x0DTCCLN78\x00K4571038A\x00MA_RES_RMV_INTRA_CHUCK\x0009\x00TCCLN78,1482479246551.044fb02eb5f873b692730b2dcbe76e13., storeName=L#0, fileCount=6, fileSize=25.8 M, priority=4, time=12099382904170064; duration=4sec {noformat} > Zookeeper connection should be closed immediately after DefaultStatisticsCollector's collecting stats done > ---------------------------------------------------------------------------------------------------------- > > Key: PHOENIX-3553 > URL: https://issues.apache.org/jira/browse/PHOENIX-3553 > Project: Phoenix > Issue Type: Bug > Affects Versions: 4.9.0 > Reporter: Yeonseop Kim > Labels: stats, zookeeper > Fix For: 4.10.0 > > Attachments: PHOENIX-3553.patch > > > In every minor compaction job of HBase, > org.apache.phoenix.schema.stats.DefaultStatisticsCollector.initGuidePostDepth() is called, > and SYSTEM.CATALOG table is open to get guidepost width via > htable = env.getTable( > SchemaUtil.getPhysicalTableName(PhoenixDatabaseMetaData.SYSTEM_CATALOG_NAME_BYTES, env.getConfiguration())); > This function call creates one zookeeper connection to get cluster id. > DefaultStatisticsCollector doesn't close this zookeeper connection immediately after get guidepost width, and the zookeeper connection remains alive until HRegion is closed. > This is not a problem with small number of Regions, but when number of Region is large and upsert operation is frequent, the number of zookeeper connection gradually increases to hundreds, and the zookeeper server nodes experience short of available TCP/IP ports. > This zookeeper connection should be closed immediately after get guidepost width. -- This message was sent by Atlassian JIRA (v6.3.4#6332)