Return-Path: X-Original-To: apmail-activemq-issues-archive@minotaur.apache.org Delivered-To: apmail-activemq-issues-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id CEB8D187A8 for ; Tue, 28 Jul 2015 19:08:04 +0000 (UTC) Received: (qmail 66201 invoked by uid 500); 28 Jul 2015 19:08:04 -0000 Delivered-To: apmail-activemq-issues-archive@activemq.apache.org Received: (qmail 66171 invoked by uid 500); 28 Jul 2015 19:08:04 -0000 Mailing-List: contact issues-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list issues@activemq.apache.org Received: (qmail 66160 invoked by uid 99); 28 Jul 2015 19:08:04 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 28 Jul 2015 19:08:04 +0000 Date: Tue, 28 Jul 2015 19:08:04 +0000 (UTC) From: "Giampaolo Tranchida (JIRA)" To: issues@activemq.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (AMQ-5695) KahaDB not cleaning up log files MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/AMQ-5695?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14644868#comment-14644868 ] Giampaolo Tranchida commented on AMQ-5695: ------------------------------------------ {code:title=Trace log with producerFlowControl="false"} 2015-07-28 20:56:16,908 [eckpoint Worker] TRACE MessageDatabase - Last update: 8:17837754, full gc candidates set: [1, 2, 3, 4, 5, 6, 7, 8] 2015-07-28 20:56:16,909 [eckpoint Worker] TRACE MessageDatabase - gc candidates after producerSequenceIdTrackerLocation:8, [1, 2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,909 [eckpoint Worker] TRACE MessageDatabase - gc candidates after ackMessageFileMapLocation:8, [1, 2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,909 [eckpoint Worker] TRACE MessageDatabase - gc candidates after tx range:[null, null], [1, 2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,911 [eckpoint Worker] TRACE MessageDatabase - gc candidates after dest:0:longTerm, [2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,911 [eckpoint Worker] TRACE MessageDatabase - gc candidates after dest:0:shortTerm, [2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,912 [eckpoint Worker] TRACE MessageDatabase - gc candidates: [2, 3, 4, 5, 6, 7] 2015-07-28 20:56:16,912 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 2 as contained ack(s) refer to referenced file: [1, 2] 2015-07-28 20:56:16,913 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 3 as contained ack(s) refer to referenced file: [2, 3] 2015-07-28 20:56:16,913 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 4 as contained ack(s) refer to referenced file: [3, 4] 2015-07-28 20:56:16,913 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 5 as contained ack(s) refer to referenced file: [4, 5] 2015-07-28 20:56:16,914 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 6 as contained ack(s) refer to referenced file: [5, 6] 2015-07-28 20:56:16,914 [eckpoint Worker] TRACE MessageDatabase - not removing data file: 7 as contained ack(s) refer to referenced file: [6, 7] 2015-07-28 20:56:16,914 [eckpoint Worker] DEBUG MessageDatabase - Checkpoint done. {code} {code:title=Trace log with producerFlowControl="true"} 2015-07-28 20:59:47,203 [eckpoint Worker] DEBUG MessageDatabase - Checkpoint started. 2015-07-28 20:59:47,393 [eckpoint Worker] TRACE MessageDatabase - Last update: 7:17837754, full gc candidates set: [1, 2, 3, 4, 5, 6, 7] 2015-07-28 20:59:47,394 [eckpoint Worker] TRACE MessageDatabase - gc candidates after producerSequenceIdTrackerLocation:7, [1, 2, 3, 4, 5, 6] 2015-07-28 20:59:47,394 [eckpoint Worker] TRACE MessageDatabase - gc candidates after ackMessageFileMapLocation:7, [1, 2, 3, 4, 5, 6] 2015-07-28 20:59:47,394 [eckpoint Worker] TRACE MessageDatabase - gc candidates after tx range:[null, null], [1, 2, 3, 4, 5, 6] 2015-07-28 20:59:47,395 [eckpoint Worker] TRACE MessageDatabase - gc candidates after dest:0:longTerm, [2, 3, 4, 5, 6] 2015-07-28 20:59:47,395 [eckpoint Worker] TRACE MessageDatabase - gc candidates after dest:0:shortTerm, [2, 3, 4, 5, 6] 2015-07-28 20:59:47,396 [eckpoint Worker] TRACE MessageDatabase - gc candidates: [2, 3, 4, 5, 6] 2015-07-28 20:59:47,396 [eckpoint Worker] DEBUG MessageDatabase - Cleanup removing the data files: [2, 3, 4, 5, 6] 2015-07-28 20:59:47,427 [eckpoint Worker] DEBUG MessageDatabase - Checkpoint done. {code} > KahaDB not cleaning up log files > -------------------------------- > > Key: AMQ-5695 > URL: https://issues.apache.org/jira/browse/AMQ-5695 > Project: ActiveMQ > Issue Type: Bug > Affects Versions: 5.11.1 > Reporter: Stefan Warten > Assignee: Arthur Naseef > > Since we have upgraded ActiveMQ from 5.10.0 to 5.11.1, KahaDB is not cleaning up log files properly. It seems to keep all of them. It helped once to restart the service and minutes later, ActiveMQ cleaned up 95% of log files but mostly it is not cleaning up at all. > When partition was full, I stopped ActiveMQ, copied the KahaDB to another host and started it with empty queues again. Then I forwarded all messages from that other host back. Even when all messages were forwarded and all queues were empty, the old KahaDB log files were not cleaned up. > I stopped ActiveMQ, removed db.data and db.redo to rebuild index which took around 3h (350GB of log files) but still, the log files are not cleaned up. > [...] > 2015-03-30 18:21:55,532 | INFO | @13786:158508, 321300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain > 2015-03-30 18:22:02,090 | INFO | Recovery replayed 321378917 operations from the journal in 9226.159 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain > 2015-03-30 18:22:02,402 | INFO | installing runtimeConfiguration plugin | org.apache.activemq.plugin.RuntimeConfigurationPlugin | WrapperSimpleAppMain > 2015-03-30 18:22:04,576 | INFO | Apache ActiveMQ 5.11.1 (prd-mig-02-sat.example.com, ID:prd-mig-02-sat.example.com-26260-1427730492201-1:1) is starting | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain > 2015-03-30 18:22:04,946 | INFO | pending local transactions: [] | org.apache.activemq.store.kahadb.MultiKahaDBTransactionStore | WrapperSimpleAppMain > 2015-03-30 18:22:08,488 | INFO | Configuration class path resource [activemq.xml] | org.apache.activemq.plugin.RuntimeConfigurationBroker | WrapperSimpleAppMain > 2015-03-30 18:22:12,198 | INFO | Listening for connections at: nio://prd-mig-02-sat.example.com:61616?transport.reuseAddress=true | org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain > 2015-03-30 18:22:12,199 | INFO | Connector openwire started | org.apache.activemq.broker.TransportConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,232 | INFO | Listening for connections at: stomp+nio://prd-mig-02-sat.example.com:61613?transport.closeAsync=false&transport.reuseAddress=true | org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain > 2015-03-30 18:22:12,234 | INFO | Connector stomp started | org.apache.activemq.broker.TransportConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,237 | INFO | Establishing network connection from vm://prd-mig-02-sat.example.com?async=false&network=true to tcp://172.42.15.40:61616 | org.apache.activemq.network.DiscoveryNetworkConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,286 | INFO | Connector vm://prd-mig-02-sat.example.com started | org.apache.activemq.broker.TransportConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,318 | INFO | Establishing network connection from vm://prd-mig-02-sat.example.com?async=false&network=true to tcp://172.42.15.39:61616 | org.apache.activemq.network.DiscoveryNetworkConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,321 | INFO | Network Connector DiscoveryNetworkConnector:FORWARDER:BrokerService[prd-mig-02-sat.example.com] started | org.apache.activemq.network.NetworkConnector | WrapperSimpleAppMain > 2015-03-30 18:22:12,325 | INFO | Apache ActiveMQ 5.11.1 (prd-mig-02-sat.example.com, ID:prd-mig-02-sat.example.com-26260-1427730492201-1:1) started | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain > 2015-03-30 18:22:12,326 | INFO | For help or more information please see: http://activemq.apache.org | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain > 2015-03-30 18:22:12,381 | INFO | Network connection between vm://prd-mig-02-sat.example.com#0 and tcp:///172.42.15.40:61616@58567 (prdvip-amq-01-sat.example.com) has been established. | org.apache.activemq.network.DemandForwardingBridgeSupport | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp:///172.42.15.40:61616@58567, localBroker= vm://prd-mig-02-sat.example.com#0 > 2015-03-30 18:22:12,381 | INFO | Network connection between vm://prd-mig-02-sat.example.com#2 and tcp:///172.42.15.39:61616@4523 (prdvip-amq-02-sat.example.com) has been established. | org.apache.activemq.network.DemandForwardingBridgeSupport | triggerStartAsyncNetworkBridgeCreation: remoteBroker=tcp:///172.42.15.39:61616@4523, localBroker= vm://prd-mig-02-sat.example.com#2 > 2015-03-31 04:21:13,971 | INFO | Slow KahaDB access: Journal append took: 0 ms, Index update took 1936 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:07:34,560 | INFO | Slow KahaDB access: cleanup took 30113 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:07:39,076 | INFO | Slow KahaDB access: cleanup took 4015 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:08:48,101 | INFO | Slow KahaDB access: Journal append took: 0 ms, Index update took 2667 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:09:39,629 | INFO | Slow KahaDB access: cleanup took 3470 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:10:20,789 | INFO | Slow KahaDB access: Journal append took: 0 ms, Index update took 2666 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:11:02,925 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2714 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:11:23,673 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2632 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:11:53,784 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2736 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:12:19,786 | INFO | Slow KahaDB access: Journal append took: 0 ms, Index update took 2663 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:13:08,826 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2770 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:13:32,862 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2819 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:14:08,931 | INFO | Slow KahaDB access: Journal append took: 0 ms, Index update took 2885 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS > 2015-03-31 06:14:42,495 | INFO | Slow KahaDB access: cleanup took 3480 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:16:13,040 | INFO | Slow KahaDB access: cleanup took 3341 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:16:43,920 | INFO | Slow KahaDB access: cleanup took 3760 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:17:14,221 | INFO | Slow KahaDB access: cleanup took 3717 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:17:44,498 | INFO | Slow KahaDB access: cleanup took 3722 | org.apache.activemq.store.kahadb.AbstractKahaDBStore | ActiveMQ Journal Checkpoint Worker > 2015-03-31 06:18:20,988 | INFO | Slow KahaDB access: Journal append took: 1 ms, Index update took 2971 ms | org.apache.activemq.store.kahadb.AbstractKahaDBStore | JobScheduler:JMS -- This message was sent by Atlassian JIRA (v6.3.4#6332)