[jira] [Comment Edited] (IMPALA-3040) test_caching_ddl failed with unexpected get_num_cache_requests

2018-06-07 Thread Tianyi Wang (JIRA) 


[ 
https://issues.apache.org/jira/browse/IMPALA-3040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16504136#comment-16504136
 ] 

Tianyi Wang edited comment on IMPALA-3040 at 6/7/18 8:43 PM:
-

In the case I looked into the problem is that the cache directive 
/test-warehouse/cachedb.db/cached_tbl_local/j=1 never got removed. The relevant 
namenode log:
{noformat}
2018-05-29 22:31:55,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:31:55,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:31:58,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:31:58,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:01,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:32:01,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:03,483 INFO 
org.apache.hadoop.hdfs.server.namenode.CacheManager: addDirective of {path: 
/test-warehouse/cachedb.db/cached_tbl_local/j=1, replication: 1, pool: 
testPool, expiration: 26687997791:19:48:13.951} successful.
2018-05-29 22:32:03,679 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning because of pending operations
2018-05-29 22:32:03,680 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
15 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:04,738 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527658324725.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755283_14459{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-45a1fee3-50a1-44cc-8230-916d08f9b968:NORMAL:127.0.0.1:31001|RBW]]}
2018-05-29 22:32:04,740 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527658324731.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755284_14460{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
2018-05-29 22:32:04,748 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527658324725
 for DFSClient_NONMAPREDUCE_-454483218_1
2018-05-29 22:32:04,748 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527658324731
 for DFSClient_NONMAPREDUCE_1562981572_1
2018-05-29 22:32:04,755 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated: 127.0.0.1:31002 is added to 
blk_1073755263_14439{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
 size 83
2018-05-29 22:32:04,755 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated: 127.0.0.1:31001 is added to 
blk_1073755264_14440{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-45a1fee3-50a1-44cc-8230-916d08f9b968:NORMAL:127.0.0.1:31001|RBW]]}
 size 83
2018-05-29 22:32:04,756 INFO org.apache.hadoop.hdfs.StateChange: DIR* 
completeFile: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527654724633
 is closed by DFSClient_NONMAPREDUCE_-454483218_1
2018-05-29 22:32:04,756 INFO org.apache.hadoop.hdfs.StateChange: DIR* 
completeFile: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527654724642
 is closed by DFSClient_NONMAPREDUCE_1562981572_1
2018-05-29 22:32:04,765 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16202,1527647515279/localhost%2C16202%2C1527647515279.default.1527658324757.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755285_14461{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
2018-05-29 22:32:04,771 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16202,1527647515279/localhost%2C16202%2C1527647515279.default.1527658324757
 for DFSClient_NONMAPREDUCE_-1203988066_1
2018-05-29 22:32:04,778 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated:

[jira] [Comment Edited] (IMPALA-3040) test_caching_ddl failed with unexpected get_num_cache_requests

2018-06-07 Thread Tianyi Wang (JIRA) 


[ 
https://issues.apache.org/jira/browse/IMPALA-3040?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16504136#comment-16504136
 ] 

Tianyi Wang edited comment on IMPALA-3040 at 6/7/18 8:23 PM:
-

In the case I looked into the problem is that the cache directive 
/test-warehouse/cachedb.db/cached_tbl_local/j=1 never got removed. The relevant 
namenode log:
{noformat}
2018-05-29 22:31:55,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:31:55,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:31:58,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:31:58,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:01,636 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning after 3000 milliseconds
2018-05-29 22:32:01,637 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
14 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:03,483 INFO 
org.apache.hadoop.hdfs.server.namenode.CacheManager: addDirective of {path: 
/test-warehouse/cachedb.db/cached_tbl_local/j=1, replication: 1, pool: 
testPool, expiration: 26687997791:19:48:13.951} successful.
2018-05-29 22:32:03,679 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: 
Rescanning because of pending operations
2018-05-29 22:32:03,680 INFO 
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: Scanned 
15 directive(s) and 7 block(s) in 1 millisecond(s).
2018-05-29 22:32:04,738 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527658324725.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755283_14459{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-45a1fee3-50a1-44cc-8230-916d08f9b968:NORMAL:127.0.0.1:31001|RBW]]}
2018-05-29 22:32:04,740 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527658324731.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755284_14460{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
2018-05-29 22:32:04,748 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527658324725
 for DFSClient_NONMAPREDUCE_-454483218_1
2018-05-29 22:32:04,748 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527658324731
 for DFSClient_NONMAPREDUCE_1562981572_1
2018-05-29 22:32:04,755 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated: 127.0.0.1:31002 is added to 
blk_1073755263_14439{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
 size 83
2018-05-29 22:32:04,755 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated: 127.0.0.1:31001 is added to 
blk_1073755264_14440{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-45a1fee3-50a1-44cc-8230-916d08f9b968:NORMAL:127.0.0.1:31001|RBW]]}
 size 83
2018-05-29 22:32:04,756 INFO org.apache.hadoop.hdfs.StateChange: DIR* 
completeFile: 
/hbase/WALs/localhost,16203,1527647516612/localhost%2C16203%2C1527647516612.default.1527654724633
 is closed by DFSClient_NONMAPREDUCE_-454483218_1
2018-05-29 22:32:04,756 INFO org.apache.hadoop.hdfs.StateChange: DIR* 
completeFile: 
/hbase/WALs/localhost,16201,1527647513859/localhost%2C16201%2C1527647513859.default.1527654724642
 is closed by DFSClient_NONMAPREDUCE_1562981572_1
2018-05-29 22:32:04,765 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocateBlock: 
/hbase/WALs/localhost,16202,1527647515279/localhost%2C16202%2C1527647515279.default.1527658324757.
 BP-1128346793-127.0.0.1-1527647465315 
blk_1073755285_14461{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, 
replicas=[ReplicaUnderConstruction[[DISK]DS-223dfda7-738f-4020-bf4c-29a4642750e1:NORMAL:127.0.0.1:31002|RBW]]}
2018-05-29 22:32:04,771 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync: 
/hbase/WALs/localhost,16202,1527647515279/localhost%2C16202%2C1527647515279.default.1527658324757
 for DFSClient_NONMAPREDUCE_-1203988066_1
2018-05-29 22:32:04,778 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap 
updated: