You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@accumulo.apache.org by "Josh Elser (JIRA)" <ji...@apache.org> on 2014/01/27 17:39:40 UTC
[jira] [Comment Edited] (ACCUMULO-2261) duplicate locations
[ https://issues.apache.org/jira/browse/ACCUMULO-2261?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13882936#comment-13882936 ]
Josh Elser edited comment on ACCUMULO-2261 at 1/27/14 4:39 PM:
---------------------------------------------------------------
We have ntp setup to synchronize system clocks. Here's the log from 192.168.2.233.
_applied jira formatting_
{noformat}
2014-01-25 09:49:11,708 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=483.68814MB (507183784), Free=1564.3119MB (1640299864), Max=2048.0MB (2147483648), Counts: Blocks=835, Access=30151167, Hit=30150280,
Miss=887, Evictions=0, Evicted=0, Ratios: Hit Ratio=99.9970555305481%, Miss Ratio=0.0029418428312055767%, Evicted/Run=NaN, Duplicate Reads=18
2014-01-25 09:49:11,711 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=6742.9854MB (7070532384), Free=1449.0149MB (1519402208), Max=8192.0MB (8589934592), Counts: Blocks=68811, Access=43909183, Hit=4336353
1, Miss=545652, Evictions=57, Evicted=476838, Ratios: Hit Ratio=98.75731468200684%, Miss Ratio=1.242683082818985%, Evicted/Run=8365.5791015625, Duplicate Reads=0
2014-01-25 09:49:11,712 [tabletserver.TabletServer] DEBUG: gc ParNew=897.13(+17.22) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=4,064,834,072(+1,745,404,552) totalmem=12,777,553,920
2014-01-25 09:49:17,455 [tabletserver.TabletServer] DEBUG: gc ParNew=901.79(+4.67) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,913,871,704(+667,572,648) totalmem=12,777,553,920
2014-01-25 09:49:17,871 [cache.LruBlockCache] DEBUG: Block cache LRU eviction started. Attempting to free 859003704 bytes
2014-01-25 09:49:17,942 [cache.LruBlockCache] DEBUG: Block cache LRU eviction completed. Freed 859019280 bytes. Priority Sizes: Single=2512.0676MB (2634093856), Multi=4456.495MB (4672973712),Memory=0.0MB (0)
2014-01-25 09:49:19,569 [tabletserver.TabletServer] DEBUG: gc ParNew=903.09(+1.30) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,733,299,800(-180,571,904) totalmem=12,777,553,920
2014-01-25 09:49:21,472 [tabletserver.TabletServer] DEBUG: gc ParNew=904.08(+0.99) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,574,451,336(-158,848,464) totalmem=12,777,553,920
2014-01-25 09:49:44,408 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,408 [tabletserver.TabletServer] INFO : Loading tablet d;72~gcm~201304;72
2014-01-25 09:49:44,408 [tabletserver.TabletServer] INFO : dcloud18/192.168.2.233:9997: got assignment from master: d;72~gcm~201304;72
2014-01-25 09:49:44,408 [tabletserver.TabletServer] DEBUG: Loading extent: d;72~gcm~201304;72
2014-01-25 09:49:44,409 [tabletserver.TabletServer] DEBUG: verifying extent d;72~gcm~201304;72
2014-01-25 09:49:44,418 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,418 [tabletserver.TabletServer] INFO : Loading tablet p;18~thm~2012101;18
2014-01-25 09:49:44,456 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,557 [tabletserver.Tablet] DEBUG: Looking at metadata {d;72~gcm~201304 file:/b-00028xn/I0002i57.rf [] 40757550 false=1625685,0,1389849852187, d;72~gcm~201304 file:/b-00028xn/I0002i5f.rf [] 40757699 false=1592695,0,1389849860660, d;72~gcm~201304 file:/t-0001ect/C0001nrv.rf [] 40418333 false=178655073,3168593, d;72~gcm~201304 file:/t-0001rzt/C0001u7r.rf [] 40441613 false=232169298,4085196, d;72~gcm~201304 file:/t-0001rzt/C0002evg.rf [] 40708788 false=281016452,4939001, d;72~gcm~201304 file:/t-0001rzt/C0002j3b.rf [] 40750189 false=36970878,670358, d;72~gcm~201304 file:/t-0001rzt/C0002j5f.rf [] 40756562 false=22086620,394464, d;72~gcm~201304 future:343bc1fa155242c [] 41048300 false=192.168.2.233:9997, d;72~gcm~201304 last:3438da6a936264c [] 40756562 false=192.168.2.225:9997, d;72~gcm~201304 srv:dir [] 40418333 false=/t-0001rzt, d;72~gcm~201304 srv:flush [] 40825738 false=9, d;72~gcm~201304 srv:lock [] 40825738 false=tservers/192.168.2.223:9997/zlock-0000000001$243b1084d9e1273, d;72~gcm~201304 srv:time [] 40757699 false=M1389849860660, d;72~gcm~201304 ~tab:~pr [] 40418333 false=^A72}
2014-01-25 09:49:44,557 [tabletserver.Tablet] DEBUG: got [] for logs for d;72~gcm~201304;72
2014-01-25 09:49:44,557 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,557 [zookeeper.ZooLock] DEBUG: Unexpected event watching lock node WatchedEvent state:Disconnected type:None path:null /accumulo/f76cacfa-e117-4999-893a-1eba79920f2c/tservers/192.168.2.233:9997/zlock-0000000000
2014-01-25 09:49:44,560 [tabletserver.TabletServer] DEBUG: gc ParNew=926.22(+22.14) secs ConcurrentMarkSweep=6.25(+0.03) secs freemem=3,477,953,072(-96,498,264) totalmem=12,777,553,920
2014-01-25 09:49:44,560 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:50:09,984 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=6630.77MB (6952866144), Free=1561.2301MB (1637068448), Max=8192.0MB (8589934592), Counts: Blocks=67662, Access=43916676, Hit=43363810, Miss=552866, Evictions=58, Evicted=485201, Ratios: Hit Ratio=98.74109625816345%, Miss Ratio=1.2588976882398129%, Evicted/Run=8365.5341796875, Duplicate Reads=0
2014-01-25 09:50:09,984 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=513.6937MB (538646880), Free=1534.3063MB (1608836768), Max=2048.0MB (2147483648), Counts: Blocks=845, Access=30157409, Hit=30156512, Miss=897, Evictions=0, Evicted=0, Ratios: Hit Ratio=99.99703168869019%, Miss Ratio=0.0029743934646830894%, Evicted/Run=NaN, Duplicate Reads=18
2014-01-25 09:50:28,730 [zookeeper.ZooCache] WARN : Zookeeper error, will retry
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /accumulo/f76cacfa-e117-4999-893a-1eba79920f2c/config/tserver.client.timeout
at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041)
at org.apache.accumulo.fate.zookeeper.ZooCache$2.run(ZooCache.java:208)
{noformat}
was (Author: anthonyf):
We have ntp setup to synchronize system clocks. Here's the log from 192.168.2.233.
2014-01-25 09:49:11,708 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=483.68814MB (507183784), Free=1564.3119MB (1640299864), Max=2048.0MB (2147483648), Counts: Blocks=835, Access=30151167, Hit=30150280,
Miss=887, Evictions=0, Evicted=0, Ratios: Hit Ratio=99.9970555305481%, Miss Ratio=0.0029418428312055767%, Evicted/Run=NaN, Duplicate Reads=18
2014-01-25 09:49:11,711 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=6742.9854MB (7070532384), Free=1449.0149MB (1519402208), Max=8192.0MB (8589934592), Counts: Blocks=68811, Access=43909183, Hit=4336353
1, Miss=545652, Evictions=57, Evicted=476838, Ratios: Hit Ratio=98.75731468200684%, Miss Ratio=1.242683082818985%, Evicted/Run=8365.5791015625, Duplicate Reads=0
2014-01-25 09:49:11,712 [tabletserver.TabletServer] DEBUG: gc ParNew=897.13(+17.22) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=4,064,834,072(+1,745,404,552) totalmem=12,777,553,920
2014-01-25 09:49:17,455 [tabletserver.TabletServer] DEBUG: gc ParNew=901.79(+4.67) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,913,871,704(+667,572,648) totalmem=12,777,553,920
2014-01-25 09:49:17,871 [cache.LruBlockCache] DEBUG: Block cache LRU eviction started. Attempting to free 859003704 bytes
2014-01-25 09:49:17,942 [cache.LruBlockCache] DEBUG: Block cache LRU eviction completed. Freed 859019280 bytes. Priority Sizes: Single=2512.0676MB (2634093856), Multi=4456.495MB (4672973712),Memory=0.0MB (0)
2014-01-25 09:49:19,569 [tabletserver.TabletServer] DEBUG: gc ParNew=903.09(+1.30) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,733,299,800(-180,571,904) totalmem=12,777,553,920
2014-01-25 09:49:21,472 [tabletserver.TabletServer] DEBUG: gc ParNew=904.08(+0.99) secs ConcurrentMarkSweep=6.22(+0.00) secs freemem=3,574,451,336(-158,848,464) totalmem=12,777,553,920
2014-01-25 09:49:44,408 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,408 [tabletserver.TabletServer] INFO : Loading tablet d;72~gcm~201304;72
2014-01-25 09:49:44,408 [tabletserver.TabletServer] INFO : dcloud18/192.168.2.233:9997: got assignment from master: d;72~gcm~201304;72
2014-01-25 09:49:44,408 [tabletserver.TabletServer] DEBUG: Loading extent: d;72~gcm~201304;72
2014-01-25 09:49:44,409 [tabletserver.TabletServer] DEBUG: verifying extent d;72~gcm~201304;72
2014-01-25 09:49:44,418 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,418 [tabletserver.TabletServer] INFO : Loading tablet p;18~thm~2012101;18
2014-01-25 09:49:44,456 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,557 [tabletserver.Tablet] DEBUG: Looking at metadata {d;72~gcm~201304 file:/b-00028xn/I0002i57.rf [] 40757550 false=1625685,0,1389849852187, d;72~gcm~201304 file:/b-00028xn/I0002i5f.rf [] 40757699 false=1592695,0,1389849860660, d;72~gcm~201304 file:/t-0001ect/C0001nrv.rf [] 40418333 false=178655073,3168593, d;72~gcm~201304 file:/t-0001rzt/C0001u7r.rf [] 40441613 false=232169298,4085196, d;72~gcm~201304 file:/t-0001rzt/C0002evg.rf [] 40708788 false=281016452,4939001, d;72~gcm~201304 file:/t-0001rzt/C0002j3b.rf [] 40750189 false=36970878,670358, d;72~gcm~201304 file:/t-0001rzt/C0002j5f.rf [] 40756562 false=22086620,394464, d;72~gcm~201304 future:343bc1fa155242c [] 41048300 false=192.168.2.233:9997, d;72~gcm~201304 last:3438da6a936264c [] 40756562 false=192.168.2.225:9997, d;72~gcm~201304 srv:dir [] 40418333 false=/t-0001rzt, d;72~gcm~201304 srv:flush [] 40825738 false=9, d;72~gcm~201304 srv:lock [] 40825738 false=tservers/192.168.2.223:9997/zlock-0000000001$243b1084d9e1273, d;72~gcm~201304 srv:time [] 40757699 false=M1389849860660, d;72~gcm~201304 ~tab:~pr [] 40418333 false=^A72}
2014-01-25 09:49:44,557 [tabletserver.Tablet] DEBUG: got [] for logs for d;72~gcm~201304;72
2014-01-25 09:49:44,557 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:49:44,557 [zookeeper.ZooLock] DEBUG: Unexpected event watching lock node WatchedEvent state:Disconnected type:None path:null /accumulo/f76cacfa-e117-4999-893a-1eba79920f2c/tservers/192.168.2.233:9997/zlock-0000000000
2014-01-25 09:49:44,560 [tabletserver.TabletServer] DEBUG: gc ParNew=926.22(+22.14) secs ConcurrentMarkSweep=6.25(+0.03) secs freemem=3,477,953,072(-96,498,264) totalmem=12,777,553,920
2014-01-25 09:49:44,560 [tabletserver.TabletServer] DEBUG: Got loadTablet message from user: !SYSTEM
2014-01-25 09:50:09,984 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=6630.77MB (6952866144), Free=1561.2301MB (1637068448), Max=8192.0MB (8589934592), Counts: Blocks=67662, Access=43916676, Hit=43363810, Miss=552866, Evictions=58, Evicted=485201, Ratios: Hit Ratio=98.74109625816345%, Miss Ratio=1.2588976882398129%, Evicted/Run=8365.5341796875, Duplicate Reads=0
2014-01-25 09:50:09,984 [cache.LruBlockCache] DEBUG: Cache Stats: Sizes: Total=513.6937MB (538646880), Free=1534.3063MB (1608836768), Max=2048.0MB (2147483648), Counts: Blocks=845, Access=30157409, Hit=30156512, Miss=897, Evictions=0, Evicted=0, Ratios: Hit Ratio=99.99703168869019%, Miss Ratio=0.0029743934646830894%, Evicted/Run=NaN, Duplicate Reads=18
2014-01-25 09:50:28,730 [zookeeper.ZooCache] WARN : Zookeeper error, will retry
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /accumulo/f76cacfa-e117-4999-893a-1eba79920f2c/config/tserver.client.timeout
at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041)
at org.apache.accumulo.fate.zookeeper.ZooCache$2.run(ZooCache.java:208)
> duplicate locations
> -------------------
>
> Key: ACCUMULO-2261
> URL: https://issues.apache.org/jira/browse/ACCUMULO-2261
> Project: Accumulo
> Issue Type: Bug
> Components: master, tserver
> Affects Versions: 1.5.0
> Environment: hadoop 2.2.0 and zookeeper 3.4.5
> Reporter: Eric Newton
> Assignee: Eric Newton
> Priority: Blocker
> Fix For: 1.5.1
>
>
> Anthony F reports the following:
> bq. I have observed a loss of data when tservers fail during bulk ingest. The keys that are missing are right around the table's splits indicating that data was lost when a tserver died during a split. I am using Accumulo 1.5.0. At around the same time, I observe the master logging a message about "Found two locations for the same extent".
> And:
> bq. I'm currently digging through the logs and will report back. Keep in mind, I'm using Accumulo 1.5.0 on a Hadoop 2.2.0 stack. To determine data loss, I have a 'ConsistencyCheckingIterator' that verifies each row has the expected data (it takes a long time to scan the whole table). Below is a quick summary of what happened. The tablet in question is "d;72~gcm~201304". Notice that it is assigned to 192.168.2.233:9997[343bc1fa155242c] at 2014-01-25 09:49:36,233. At 2014-01-25 09:49:54,141, the tserver goes away. Then, the tablet gets assigned to 192.168.2.223:9997[143bc1f14412432] and shortly after that, I see the BadLocationStateException. The master never recovers from the BLSE - I have to manually delete one of the offending locations.
> {noformat}
> 2014-01-25 09:49:36,233 [master.Master] DEBUG: Normal Tablets assigning tablet d;72~gcm~201304;72=192.168.2.233:9997[343bc1fa155242c]
> 2014-01-25 09:49:36,233 [master.Master] DEBUG: Normal Tablets assigning tablet p;18~thm~2012101;18=192.168.2.233:9997[343bc1fa155242c]
> 2014-01-25 09:49:54,141 [master.Master] WARN : Lost servers [192.168.2.233:9997[343bc1fa155242c]]
> 2014-01-25 09:49:56,866 [master.Master] DEBUG: 42 assigned to dead servers: [d;03~u36~201302;03~thm~2012091@(null,192.168.2.233:9997[343bc1fa155242c],null), d;06~u36~2013;06~thm~2012083@(null,192.168.2.233:9997[343bc1fa155242c],null), d;25;24~u36~2013@(null,192.168.2.233:9997[343bc1fa155242c],null), d;25~u36~201303;25~thm~201209@(null,192.168.2.233:9997[343bc1fa155242c],null), d;27~gcm~2013041;27@(null,192.168.2.233:9997[343bc1fa155242c],null), d;30~u36~2013031;30~thm~2012082@(null,192.168.2.233:9997[343bc1fa155242c],null), d;34~thm;34~gcm~2013022@(null,192.168.2.233:9997[343bc1fa155242c],null), d;39~thm~20121;39~gcm~20130418@(null,192.168.2.233:9997[343bc1fa155242c],null), d;41~thm;41~gcm~2013041@(null,192.168.2.233:9997[343bc1fa155242c],null), d;42~u36~201304;42~thm~20121@(null,192.168.2.233:9997[343bc1fa155242c],null), d;45~thm~201208;45~gcm~201303@(null,192.168.2.233:9997[343bc1fa155242c],null), d;48~gcm~2013052;48@(null,192.168.2.233:9997[343bc1fa155242c],null), d;60~u36~2013021;60~thm~20121@(null,192.168.2.233:9997[343bc1fa155242c],null), d;68~gcm~2013041;68@(null,192.168.2.233:9997[343bc1fa155242c],null), d;72;71~u36~2013@(null,192.168.2.233:9997[343bc1fa155242c],null), d;72~gcm~201304;72@(192.168.2.233:9997[343bc1fa155242c],null,null), d;75~thm~2012101;75~gcm~2013032@(null,192.168.2.233:9997[343bc1fa155242c],null), d;78;77~u36~201305@(null,192.168.2.233:9997[343bc1fa155242c],null), d;90~u36~2013032;90~thm~2012092@(null,192.168.2.233:9997[343bc1fa155242c],null), d;91~thm;91~gcm~201304@(null,192.168.2.233:9997[343bc1fa155242c],null), d;93~u36~2013012;93~thm~20121@(null,192.168.2.233:9997[343bc1fa155242c],null), m;20;19@(null,192.168.2.233:9997[343bc1fa155242c],null), m;38;37@(null,192.168.2.233:9997[343bc1fa155242c],null), m;51;50@(null,192.168.2.233:9997[343bc1fa155242c],null), m;60;59@(null,192.168.2.233:9997[343bc1fa155242c],null), m;92;91@(null,192.168.2.233:9997[343bc1fa155242c],null), o;01<@(null,192.168.2.233:9997[343bc1fa155242c],null), o;04;03@(null,192.168.2.233:9997[343bc1fa155242c],null), o;50;49@(null,192.168.2.233:9997[343bc1fa155242c],null), o;63;62@(null,192.168.2.233:9997[343bc1fa155242c],null), o;74;73@(null,192.168.2.233:9997[343bc1fa155242c],null), o;97;96@(null,192.168.2.233:9997[343bc1fa155242c],null), p;08~thm~20121;08@(null,192.168.2.233:9997[343bc1fa155242c],null), p;09~thm~20121;09@(null,192.168.2.233:9997[343bc1fa155242c],null), p;10;09~thm~20121@(null,192.168.2.233:9997[343bc1fa155242c],null), p;18~thm~2012101;18@(192.168.2.233:9997[343bc1fa155242c],null,null), p;21;20~thm~201209@(null,192.168.2.233:9997[343bc1fa155242c],null), p;22~thm~2012091;22@(null,192.168.2.233:9997[343bc1fa155242c],null), p;23;22~thm~2012091@(null,192.168.2.233:9997[343bc1fa155242c],null), p;41~thm~2012111;41@(null,192.168.2.233:9997[343bc1fa155242c],null), p;42;41~thm~2012111@(null,192.168.2.233:9997[343bc1fa155242c],null), p;58~thm~201208;58@(null,192.168.2.233:9997[343bc1fa155242c],null)]...
> 2014-01-25 09:49:59,706 [master.Master] DEBUG: Normal Tablets assigning tablet d;72~gcm~201304;72=192.168.2.223:9997[143bc1f14412432]
> 2014-01-25 09:50:13,515 [master.EventCoordinator] INFO : tablet d;72~gcm~201304;72 was loaded on 192.168.2.223:9997
> 2014-01-25 09:51:20,058 [state.MetaDataTableScanner] ERROR: java.lang.RuntimeException: org.apache.accumulo.server.master.state.TabletLocationState$BadLocationStateException: found two locations for the same extent d;72~gcm~201304: 192.168.2.223:9997[143bc1f14412432] and 192.168.2.233:9997[343bc1fa155242c]
> java.lang.RuntimeException: org.apache.accumulo.server.master.state.TabletLocationState$BadLocationStateException: found two locations for the same extent d;72~gcm~201304: 192.168.2.223:9997[143bc1f14412432] and 192.168.2.233:9997[343bc1fa155242c]
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)