accumulo-notifications mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Josh Elser (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (ACCUMULO-2261) duplicate locations
Date Mon, 27 Jan 2014 16:39:40 GMT

    [ 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)

Mime
View raw message