From dev-return-42510-archive-asf-public=cust-asf.ponee.io@ignite.apache.org Tue Nov 27 16:04:23 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id A4EBB180670 for ; Tue, 27 Nov 2018 16:04:22 +0100 (CET) Received: (qmail 83965 invoked by uid 500); 27 Nov 2018 15:04:21 -0000 Mailing-List: contact dev-help@ignite.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ignite.apache.org Delivered-To: mailing list dev@ignite.apache.org Received: (qmail 83950 invoked by uid 99); 27 Nov 2018 15:04:21 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 27 Nov 2018 15:04:21 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 7AFBD180B81 for ; Tue, 27 Nov 2018 15:04:20 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.997 X-Spam-Level: * X-Spam-Status: No, score=1.997 tagged_above=-999 required=6.31 tests=[DKIMWL_WL_MED=-0.001, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H2=-0.001, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd3-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gridgain-com.20150623.gappssmtp.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id ttxRKLS5BKcp for ; Tue, 27 Nov 2018 15:04:16 +0000 (UTC) Received: from mail-vs1-f54.google.com (mail-vs1-f54.google.com [209.85.217.54]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id 840195F478 for ; Tue, 27 Nov 2018 15:04:16 +0000 (UTC) Received: by mail-vs1-f54.google.com with SMTP id b74so13900593vsd.9 for ; Tue, 27 Nov 2018 07:04:16 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gridgain-com.20150623.gappssmtp.com; s=20150623; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=EDxCxm7dNdOJBT/Y8N7gIFBWHcejNCmdSmFfRtbDbNM=; b=yuDcZei2kOILy4QpA9OMtIDbPBy0/Yc2ARko61Z48oIx9lzxIu3QrLSsPu8vyYkQd2 pUxq7PxsGmu2sHvh4V6hqq9+Iz1TH2y1soGD/MEFMMkS9Ike6NaldCckM90Vb6KKsKHh SkF/fAhd1vDoYTEC3GDvihWHIaU0f/7cpe74l0kZnIKo9EA04S9oB78XWTKiLr84Tlje rl2Nxz1wvMLlsqEmyS1kgAG2376TYTV9hmS8duklsAmlG6Hbrt+ct2Aw8b+FeP0rfDp6 lDZZphj46XGsAhz8wr7MnBPzsiJkF1bVCf7QhjaJ103yuH3YN4ywXNSV7frXixrcYujG 0kqg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=EDxCxm7dNdOJBT/Y8N7gIFBWHcejNCmdSmFfRtbDbNM=; b=Zr8ufp/O7RcMed7yflhpMZhvf9uPpkPt+BqIqS9qVisTGAZNk6yCtSsfBAS9EuPDvq TMYU5sHLcMs5K+oPfbcgA65vb8mIbjmQNeStMvPrsLisxZCU6jJ5Ima3qRSJjx+dNikD MRUUitAcJtTrqw2wBKVVHk1XEnMUc+ijOIlZ25UvdJruvxYDn30luRWFO4bR/KlUEU23 3055AxSFgAzVQFHrke8SRp5Q6Zo3iRqBXQ1WqMdBymg1tbBiDh50lq5Hspto3Le2S6Zv OOPsXzNmZPiU+HUN9i8esWG9kolBFtghadtvkuMrAJcBR1o8oo4hRBDhYSXHIeiHQUNO QB2g== X-Gm-Message-State: AGRZ1gJzEsoNb8OYTDmzZdJtDy5IuIwE8cZZ8pFAugLzcRYeqwWl1IIw o85fLgWvARnWNgs7fmKtbt7meCaKNdgOOgVUnxSX3l3u X-Google-Smtp-Source: AJdET5cZ8VWzV1l9kGzjBmtZeRk9xz9a+u29p2KCvBYiMgHcs9QXLwthEFdWph3Q0MFbQwwYP7YsUUZbR18messRhfM= X-Received: by 2002:a67:1346:: with SMTP id 67mr12336702vst.31.1543331055159; Tue, 27 Nov 2018 07:04:15 -0800 (PST) MIME-Version: 1.0 References: In-Reply-To: From: Vladimir Ozerov Date: Tue, 27 Nov 2018 18:04:02 +0300 Message-ID: Subject: Re: Lightweight profiling of messages processing To: dev Content-Type: multipart/alternative; boundary="00000000000050e7a0057ba6c3e6" --00000000000050e7a0057ba6c3e6 Content-Type: text/plain; charset="UTF-8" Clarification: p.5 is about buffer pool and disk access statistics, not network. On Tue, Nov 27, 2018 at 6:02 PM Vladimir Ozerov wrote: > Alexey, > > I would say that to implement this feature successfully, we first need to > clearly understand specific scenarios we want to target, and only then plan > implementation in small iterations. Please take in count the following > points: > 1) Splitting by message type might be too fine-grained thing for the first > iteration. For example, we have N different message types processed in a > system pool. Add several messages causing long-running tasks (e.g. invoke), > and deque time will grow for all other message types for the same queue. I > think we can start with a simpler metrics - per-pool queueing time, pool > throughput, pool task latencies. This would be enough for a wide number of > use cases. We may expand it in future if needed. > 2) Some IO statistics were already implemented as a part of IGNITE-6868 > [1]. See TcpCommunicationSpiMBeanImpl. You may find it useful for your task. > 3) Public API should be designed upfront. Normally it should include JMX > and system SQL views (e.g. like [2]). JMX is useful for external tools, SQL > views allow access to performance data from all platforms all at once. This > is critical. > 4) It should be possible to enable/disable such metrics in runtime. > Probably infrastructure from IGNITE-369 [3] might be reused for this > purpose (see GridCacheProcessor.EnableStatisticsFuture) > 5) IO access statistics are already under development [4]. First part will > be merged very soon. > 5) Performance effects must be measured extremely carefully in all modes > (in-memory, persistence, background/log_only/fsync), because you are likely > to change very performance sensitive code pieces. We had a lot of > performance issues when implementing IGNITE-6868 [1]. > > Vladimir. > > [1] https://issues.apache.org/jira/browse/IGNITE-6868 > [1] https://issues.apache.org/jira/browse/IGNITE-7700 > [3] https://issues.apache.org/jira/browse/IGNITE-369 > [4] > https://cwiki.apache.org/confluence/display/IGNITE/IEP-27%3A+Page+IO+statistics > > On Tue, Nov 27, 2018 at 5:04 PM Alexey Kukushkin < > kukushkinalexey@gmail.com> wrote: > >> Hi Alexei, >> >> Did you consider general-purpose APM >> tools >> like free InspectIT or >> commercial >> DynaTrace or AppDynamics >> ? >> >> Java APM tools do not require writing code or even instrumenting Ignite >> binaries: you just attach them as javaagent >> >> to >> Ignite JVM and then you can configure "sensors" to track whatever API you >> want. APM tools collect metrics from the sensors and provide sophisticated >> analysis tools. >> >> DynaTrace claims they have 2%-7% overhead (depending on application) but >> you can always detach the tool if you do not always need it in production. >> >> I did not try APM for Ignite myself but it might work well. >> >> On Tue, Nov 27, 2018 at 4:37 PM Alexei Scherbakov < >> alexey.scherbakoff@gmail.com> wrote: >> >> > Igniters, >> > >> > At work I often have to solve performance issues with Ignite cluster >> > without having access to source code of running user application. >> > >> > Looks like Ignite have limited capabilities to identify bottlenecks >> without >> > extensive profiling on server and client side (JFR recording , sampling >> > profilers, regular thread dumps, etc), which is not always possible. >> > >> > Even having profiling data not always helpful for determining several >> types >> > of bottlenecks, on example, if where is a contention on single >> > key/partition. >> > >> > I propose to implement new feature, like lightweight profiling of >> message >> > processing. >> > >> > The feature will allow to have view on message processing statistics for >> > each node and for all grid nodes. >> > >> > In short, it's necessary to track each message execution in executors >> and >> > record execution statistics like synchronous execution time in executor >> > thread and waiting time in queue. >> > >> > Full description: >> > >> > 1. Implement detailed tracking of message waiting in queue and actual >> > processing by executors with splitting to several time bins. Example of >> > detailed statistics for each processed message: >> > >> > >> > Processing time(%) >> > Message Total Average(ms) >> > < 1 ms < 10 ms < 30ms < 50ms < 100ms < 250ms < >> > 500ms < 750ms < 1000ms > 1000ms >> > >> > >> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> > GridNearSingleGetRequest 904311372 0.023000 >> > 904240521 57394 7242 3961 1932 229 >> > 61 24 4 4 >> > GridNearSingleGetResponse 340134416 0.041000 >> > 340118791 11660 1167 729 901 1001 >> > 158 8 1 0 >> > GridNearLockRequest 77088689 0.079000 >> > 77073458 11945 2299 643 311 31 >> > 2 0 0 0 >> > GridNearAtomicSingleUpdateInvokeRequest 39645752 0.298000 >> > 39580914 28222 6469 4638 9870 13414 >> > 2087 137 1 0 >> > GridDhtAtomicSingleUpdateRequest 37636829 0.277000 >> > 37579375 23247 5915 4210 8954 12917 >> > 2048 162 1 0 >> > GridDhtAtomicDeferredUpdateResponse 33580198 0.002000 >> > 33579805 337 51 3 1 1 >> > 0 0 0 0 >> > GridNearTxPrepareRequest 21667790 0.238000 >> > 21078069 580126 1622 1261 2531 3631 >> > 496 40 0 14 >> > GridDhtTxPrepareResponse 20949873 0.316000 >> > 17130161 3803105 4615 3162 4489 3721 >> > 577 34 1 8 >> > GridDhtTxPrepareRequest 20949838 0.501000 >> > 16158732 4750217 16183 5735 8472 8994 >> > 1353 88 11 53 >> > GridDhtTxFinishResponse 13835065 0.007000 >> > 13832519 2476 27 28 14 1 >> > 0 0 0 0 >> > GridDhtTxFinishRequest 13835028 0.547000 >> > 12084106 1736789 8971 2340 1792 807 >> > 118 41 4 60 >> > GridNearTxFinishRequest 13762197 0.725000 >> > 11811828 1942499 4441 1400 1201 524 >> > 89 34 19 162 >> > GridDhtAtomicNearResponse 2784422 0.122000 >> > 2783393 1022 5 2 0 0 >> > 0 0 0 0 >> > GridNearGetRequest 2360483 0.484000 >> > 2345937 14129 244 101 64 8 >> > 0 0 0 0 >> > GridNearGetResponse 1984243 0.054000 >> > 1981905 2327 8 1 1 1 >> > 0 0 0 0 >> > GridNearTxPrepareResponse 192856 0.153000 >> > 192660 188 1 5 1 1 >> > 0 0 0 0 >> > GridNearLockResponse 192780 0.091000 >> > 192667 107 3 0 3 0 >> > 0 0 0 0 >> > GridNearTxFinishResponse 177 0.822000 >> > 129 47 1 0 0 0 >> > 0 0 0 0 >> > GridNearAtomicSingleUpdateRequest 124 4.803000 >> > 52 53 19 0 0 0 >> > 0 0 0 0 >> > GridNearAtomicUpdateResponse 120 0.448000 >> > 110 10 0 0 0 0 >> > 0 0 0 0 >> > >> > >> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> > 1544912252 >> > 1531765132 12965900 59283 28219 40537 45281 >> > 6989 568 42 301 >> > >> > >> > Queue waiting time(%) >> > Message Total Average(ms) >> > < 1 ms < 10 ms < 30ms < 50ms < 100ms < 250ms < >> > 500ms < 750ms < 1000ms > 1000ms >> > >> > >> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> > GridNearSingleGetRequest 904311372 0.023000 >> > 903130400 1051499 33248 18049 34044 38809 >> > 4714 212 8 389 >> > GridNearSingleGetResponse 340134416 0.041000 >> > 339708055 419479 3732 1004 1222 737 >> > 117 2 1 67 >> > GridNearLockRequest 77088689 0.079000 >> > 76949792 129666 2003 1624 2585 2531 >> > 390 18 2 78 >> > GridNearAtomicSingleUpdateInvokeRequest 39645752 0.298000 >> > 39572801 53913 3949 2960 5487 5583 >> > 963 45 5 46 >> > GridDhtAtomicSingleUpdateRequest 37636829 0.277000 >> > 37561043 57294 3721 2736 5339 5716 >> > 879 54 6 41 >> > GridDhtAtomicDeferredUpdateResponse 33580198 0.002000 >> > 33512734 45873 4427 3340 6342 6363 >> > 1033 50 10 26 >> > GridNearTxPrepareRequest 21667790 0.238000 >> > 21584416 76283 1681 1026 1948 2027 >> > 330 31 2 46 >> > GridDhtTxPrepareResponse 20949873 0.316000 >> > 20862632 83578 1214 633 821 817 >> > 118 26 8 26 >> > GridDhtTxPrepareRequest 20949838 0.501000 >> > 20867551 72264 2265 1516 2773 2905 >> > 479 38 6 41 >> > GridDhtTxFinishResponse 13835065 0.007000 >> > 13808274 26487 150 68 55 21 >> > 3 1 0 6 >> > GridDhtTxFinishRequest 13835028 0.547000 >> > 13809380 25142 188 127 102 59 >> > 9 2 4 15 >> > GridNearTxFinishRequest 13762197 0.725000 >> > 13743925 17365 241 171 278 191 >> > 16 4 0 6 >> > GridDhtAtomicNearResponse 2784422 0.122000 >> > 2780600 3767 29 9 7 9 >> > 1 0 0 0 >> > GridNearGetRequest 2360483 0.484000 >> > 2355963 3762 194 114 184 228 >> > 38 0 0 0 >> > GridNearGetResponse 1984243 0.054000 >> > 1979404 4721 31 9 49 28 >> > 1 0 0 0 >> > GridNearTxPrepareResponse 192856 0.153000 >> > 192852 2 0 1 1 0 >> > 0 0 0 0 >> > GridNearLockResponse 192780 0.091000 >> > 192777 3 0 0 0 0 >> > 0 0 0 0 >> > GridNearTxFinishResponse 177 0.822000 >> > 177 0 0 0 0 0 >> > 0 0 0 0 >> > GridNearAtomicSingleUpdateRequest 124 4.803000 >> > 124 0 0 0 0 0 >> > 0 0 0 0 >> > GridNearAtomicUpdateResponse 120 0.448000 >> > 119 1 0 0 0 0 >> > 0 0 0 0 >> > >> > >> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> > 1544912252 >> > 1542613019 2071099 57073 33387 61237 66024 >> > 9091 483 52 787 >> > >> > >> > This will allow to understand cluster load type and presence of problems >> > with increased latency in message processing. In general all messages >> > should be processed within time < 30ms. >> > >> > 2. Log messages which are waiting too long or have been processed for >> too >> > long (this is configured threshold). >> > >> > Track the following: message enqueue time, waiting in queue until >> > processing is started, head of queue before starting to wait, queue size >> > before starting to wait, total waiting time, total processing time, >> queue >> > size after processing, message content. Example: >> > >> > Slow message: *enqueueTs*=2018-11-27 15:10:22.241, *waitTime*=0.048, >> > *procTime*=305.186, *messageId*=3a3064a9, *queueSzBefore*=0, >> > *headMessageId*=null, >> > *queueSzAfter*=0, *message*=GridNearTxFinishRequest [miniId=1, >> > mvccSnapshot=null, super=GridDistributedTxFinishRequest >> > [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0], >> > futId=199a3155761-f379f312-ad4b-4181-acc5-0aacb3391f07, threadId=296, >> > commitVer=null, invalidate=false, commit=true, baseVer=null, txSize=0, >> > sys=false, plc=2, subjId=dda703a0-69ee-47cf-9b9a-bf3dc9309feb, >> > taskNameHash=0, flags=32, syncMode=FULL_SYNC, txState=IgniteTxStateImpl >> > [activeCacheIds=[644280847], recovery=false, mvccEnabled=false, >> > txMap=HashSet [IgniteTxEntry [key=KeyCacheObjectImpl [part=8, val=8, >> > hasValBytes=true], cacheId=644280847, txKey=IgniteTxKey >> > [key=KeyCacheObjectImpl [part=8, val=8, hasValBytes=true], >> > cacheId=644280847], val=[op=READ, val=null], prevVal=[op=NOOP, >> val=null], >> > oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, >> > conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, >> > filters=CacheEntryPredicate[] [], filtersPassed=false, filtersSet=false, >> > entry=GridCacheMapEntry [key=KeyCacheObjectImpl [part=8, val=8, >> > hasValBytes=true], val=null, ver=GridCacheVersion [topVer=0, order=0, >> > nodeOrder=0], hash=8, extras=GridCacheObsoleteEntryExtras >> > [obsoleteVer=GridCacheVersion [topVer=2147483647, order=0, >> nodeOrder=0]], >> > flags=2]GridDistributedCacheEntry [super=]GridDhtCacheEntry >> > [rdrs=ReaderId[] [], part=8, super=], prepared=0, locked=false, >> > nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, >> > flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion >> > [topVer=154800617, order=1543320621588, nodeOrder=1]], IgniteTxEntry >> > [key=KeyCacheObjectImpl [part=11, val=11, hasValBytes=true], >> > cacheId=644280847, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=11, >> > val=11, hasValBytes=true], cacheId=644280847], val=[op=READ, val=null], >> > prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], >> > entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, >> conflictVer=null, >> > explicitVer=null, dhtVer=null, filters=CacheEntryPredicate[] [], >> > filtersPassed=false, filtersSet=false, entry=GridCacheMapEntry >> > [key=KeyCacheObjectImpl [part=11, val=11, hasValBytes=true], val=null, >> > ver=GridCacheVersion [topVer=0, order=0, nodeOrder=0], hash=11, >> > extras=GridCacheObsoleteEntryExtras [obsoleteVer=GridCacheVersion >> > [topVer=2147483647, order=0, nodeOrder=0]], >> > flags=2]GridDistributedCacheEntry [super=]GridDhtCacheEntry >> > [rdrs=ReaderId[] [], part=11, super=], prepared=0, locked=false, >> > nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, >> > flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion >> > [topVer=154800617, order=1543320621588, nodeOrder=1]]]], >> > super=GridDistributedBaseMessage [ver=GridCacheVersion >> [topVer=154800617, >> > order=1543320621587, nodeOrder=4], committedVers=null, >> rolledbackVers=null, >> > cnt=0, super=GridCacheIdMessage [cacheId=0]]]] >> > >> > This will allow to understand type of activity which produces latency >> > issues and possibly identify culprit code. >> > >> > 3. Track all synchronous waits while processing message: checkpoint >> locks, >> > segment locks, page locks, cold page reads from disk, etc. >> > >> > 4. Allow extensions to collection additional statistics for specific >> > message type. On example, for *TxFinishRequest we could track total >> > entities written for each cache and size in bytes. For >> GridNearLockRequest >> > we could track keys with max lock queue length for identifying >> contention. >> > >> > 5. Implement additional logging, JMX metrics and control.sh command for >> > printing currently collected profiling data. >> > >> > 6. Implementation should be as lightweight as possible. >> > >> > Maybe something else. >> > >> > BTW, I already started working on it and want to contribute my work to >> > community. Ticket with PR (not finished) [1], check for >> > CacheMessageStatsTest and CacheMessageStatsIndexingTest >> > >> > [1] https://issues.apache.org/jira/browse/IGNITE-10418 >> > >> > Thoughts ? >> > >> > -- >> > >> > Best regards, >> > Alexei Scherbakov >> > >> >> >> -- >> Best regards, >> Alexey >> > --00000000000050e7a0057ba6c3e6--