Return-Path: Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: (qmail 65365 invoked from network); 16 Sep 2010 22:03:58 -0000 Received: from unknown (HELO mail.apache.org) (140.211.11.3) by 140.211.11.9 with SMTP; 16 Sep 2010 22:03:58 -0000 Received: (qmail 49646 invoked by uid 500); 16 Sep 2010 22:03:58 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 49521 invoked by uid 500); 16 Sep 2010 22:03:57 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 49511 invoked by uid 99); 16 Sep 2010 22:03:57 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 16 Sep 2010 22:03:57 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.22] (HELO thor.apache.org) (140.211.11.22) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 16 Sep 2010 22:03:54 +0000 Received: from thor (localhost [127.0.0.1]) by thor.apache.org (8.13.8+Sun/8.13.8) with ESMTP id o8GM3XOI000332 for ; Thu, 16 Sep 2010 22:03:33 GMT Message-ID: <7051889.238731284674613228.JavaMail.jira@thor> Date: Thu, 16 Sep 2010 18:03:33 -0400 (EDT) From: "ryan rawson (JIRA)" To: issues@hbase.apache.org Subject: [jira] Commented: (HBASE-3006) Reading compressed HFile blocks causes way too many DFS RPC calls severly impacting performance In-Reply-To: <4399245.232951284655292677.JavaMail.jira@thor> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 X-Virus-Checked: Checked by ClamAV on apache.org [ https://issues.apache.org/jira/browse/HBASE-3006?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12910343#action_12910343 ] ryan rawson commented on HBASE-3006: ------------------------------------ if the objects are short lived, it doesnt matter the object allocation size. If they are used only for the lifecycle of reading a single block, i'd say size it to the compressed Size. > Reading compressed HFile blocks causes way too many DFS RPC calls severly impacting performance > ----------------------------------------------------------------------------------------------- > > Key: HBASE-3006 > URL: https://issues.apache.org/jira/browse/HBASE-3006 > Project: HBase > Issue Type: Bug > Affects Versions: 0.89.20100621 > Reporter: Kannan Muthukkaruppan > Assignee: Kannan Muthukkaruppan > Priority: Critical > Attachments: HBASE-3006.txt > > > On some read perf tests, we noticed several perf outliers (10 second plus range). The rows were large (spanning multiple blocks, but still the numbers didn't add up). We had compression turned on. > We enabled DN clienttrace logging, > log4j.logger.org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace=DEBUG > and noticed lots of 516 byte reads at the DN level, several of them at the same offset in the block. > {code} > 2010-09-16 09:28:32,335 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:38713, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 203000 > 2010-09-16 09:28:32,336 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:40547, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 119000 > 2010-09-16 09:28:32,337 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:40650, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 149000 > 2010-09-16 09:28:32,337 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:40861, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 135000 > 2010-09-16 09:28:32,338 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:41129, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 117000 > 2010-09-16 09:28:32,339 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:41691, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 148000 > 2010-09-16 09:28:32,339 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:42881, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 114000 > 2010-09-16 09:28:32,341 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:49511, bytes: 516, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.3\ > 0.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 153000 > 2010-09-16 09:28:32,342 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.30.251.189:50010, dest: /10.30.251.189:51158, bytes: 3096, op: HDFS_READ, cliID: DFSClient_-436329957, offset: 39884800, srvID: DS-1757894045-10.\ > 30.251.189-50010-1283993662994, blockid: blk_-4686540439725119008_1985, duration: 139000 > {code} > This was strange coz our block size was 64k, and on disk block size after compression should generally have been around 6k. > Some print debugging at the HFile and BoundedRangeFileInputStream (which is wrapped by createDecompressionStream) revealed the following: > We are trying to read 20k from DFS @ HFile layer. The BounderRangeFileInputStream instead reads several header bytes 1 byte at a time, and then reads a 11k chunk and later a 9k chunk. > {code} > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.HFile: ### fs read @ offset = 34386760 compressedSize = 20711 decompressedSize = 92324 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386760; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386761; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386762; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386763; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386764; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386765; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386766; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386767; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34386768; bytes: 11005 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397773; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397774; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397775; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397776; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397777; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397778; bytes: 1 > 2010-09-16 09:21:27,912 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397779; bytes: 1 > 2010-09-16 09:21:27,913 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397780; bytes: 1 > 2010-09-16 09:21:27,913 INFO org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream: ### seeking to reading @ 34397781; bytes: 9690 > {code} > Seems like it should be an easy fix to prefetch the compressed size... rather than incremental fetches. -- This message is automatically generated by JIRA. - You can reply to this email to add a comment to the issue online.