Marta Kuczora created HIVE-15282:
------------------------------------

             Summary: Different modification times are used when an index is 
built and when its staleness is checked
                 Key: HIVE-15282
                 URL: https://issues.apache.org/jira/browse/HIVE-15282
             Project: Hive
          Issue Type: Bug
          Components: Indexing
    Affects Versions: 2.1.0
            Reporter: Marta Kuczora
            Assignee: Marta Kuczora


The index_auto_mult_tables and index_auto_mult_tables_compact q tests are 
failing from time to time with the following error:
{noformat}
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_index_auto_mult_tables

Failing for the past 1 build (Since Failed#16 )
Took 16 sec.
Error Message

Unexpected exception junit.framework.AssertionFailedError: Client Execution 
results failed with error code = 1
See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
 at junit.framework.Assert.fail(Assert.java:57)
 at org.apache.hadoop.hive.ql.QTestUtil.failedDiff(QTestUtil.java:2001)
 at org.apache.hadoop.hive.cli.TestCliDriver.runTest(TestCliDriver.java:194)
 at 
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_index_auto_mult_tables(TestCliDriver.java:142)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
 at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
 at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
 at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
 at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
 at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
 at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
 at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
 at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
 at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
 at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
 at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
 at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
 at 
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
 at 
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
 at 
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
 at 
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
 at 
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
 at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)


See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
Stacktrace

junit.framework.AssertionFailedError: Unexpected exception 
junit.framework.AssertionFailedError: Client Execution results failed with 
error code = 1
See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
        at junit.framework.Assert.fail(Assert.java:57)
        at org.apache.hadoop.hive.ql.QTestUtil.failedDiff(QTestUtil.java:2001)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.runTest(TestCliDriver.java:194)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_index_auto_mult_tables(TestCliDriver.java:142)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
        at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
        at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
        at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
        at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
        at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
        at 
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
        at 
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
        at 
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)


See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
        at junit.framework.Assert.fail(Assert.java:57)
        at org.apache.hadoop.hive.ql.QTestUtil.failed(QTestUtil.java:2011)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.runTest(TestCliDriver.java:198)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_index_auto_mult_tables(TestCliDriver.java:142)
Standard Output

Running: diff -a 
/home/hiveptest/hive-ptest-cloudera-slaves-0c70-6.vpc.cloudera.com-hiveptest-1/cdh-source/itests/qtest/../../itests/qtest/target/qfile-results/clientpositive/index_auto_mult_tables.q.out
 
/home/hiveptest/hive-ptest-cloudera-slaves-0c70-6.vpc.cloudera.com-hiveptest-1/cdh-source/itests/qtest/../../ql/src/test/results/clientpositive/index_auto_mult_tables.q.out
216c216,218
<   Stage-1 depends on stages: Stage-3
---
>   Stage-1 depends on stages: Stage-3, Stage-5
>   Stage-6 is a root stage
>   Stage-5 depends on stages: Stage-6
224,225c226,227
<             alias: default__src_src_index__
<             filterExpr: (((((UDFToDouble(key) > 80.0) and (UDFToDouble(key) < 
100.0)) and (UDFToDouble(key) > 70.0)) and (UDFToDouble(key) < 90.0)) and (not 
EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
---
>             alias: default__srcpart_srcpart_index__
>             filterExpr: (((((UDFToDouble(key) > 70.0) and (UDFToDouble(key) < 
> 90.0)) and (UDFToDouble(key) > 80.0)) and (UDFToDouble(key) < 100.0)) and 
> (not EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
227c229
<               predicate: (((((UDFToDouble(key) > 80.0) and (UDFToDouble(key) 
< 100.0)) and (UDFToDouble(key) > 70.0)) and (UDFToDouble(key) < 90.0)) and 
(not EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
---
>               predicate: (((((UDFToDouble(key) > 70.0) and (UDFToDouble(key) 
> < 90.0)) and (UDFToDouble(key) > 80.0)) and (UDFToDouble(key) < 100.0)) and 
> (not EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
316a319,358
>   Stage: Stage-6
>     Map Reduce
>       Map Operator Tree:
>           TableScan
>             alias: default__src_src_index__
>             filterExpr: (((((UDFToDouble(key) > 80.0) and (UDFToDouble(key) < 
> 100.0)) and (UDFToDouble(key) > 70.0)) and (UDFToDouble(key) < 90.0)) and 
> (not EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
>             Filter Operator
>               predicate: (((((UDFToDouble(key) > 80.0) and (UDFToDouble(key) 
> < 100.0)) and (UDFToDouble(key) > 70.0)) and (UDFToDouble(key) < 90.0)) and 
> (not EWAH_BITMAP_EMPTY(_bitmaps))) (type: boolean)
>               Select Operator
>                 expressions: _bucketname (type: string), _offset (type: 
> bigint)
>                 outputColumnNames: _col0, _col1
>                 Group By Operator
>                   aggregations: collect_set(_col1)
>                   keys: _col0 (type: string)
>                   mode: hash
>                   outputColumnNames: _col0, _col1
>                   Reduce Output Operator
>                     key expressions: _col0 (type: string)
>                     sort order: +
>                     Map-reduce partition columns: _col0 (type: string)
>                     value expressions: _col1 (type: array<bigint>)
>       Reduce Operator Tree:
>         Group By Operator
>           aggregations: collect_set(VALUE._col0)
>           keys: KEY._col0 (type: string)
>           mode: mergepartial
>           outputColumnNames: _col0, _col1
>           File Output Operator
>             compressed: false
>             table:
>                 input format: org.apache.hadoop.mapred.TextInputFormat
>                 output format: 
> org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat
>                 serde: org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe
> 
>   Stage: Stage-5
>     Move Operator
>       files:
>           hdfs directory: true
> #### A masked pattern was here ####
> 
325a368,372
> PREHOOK: Input: default@default__srcpart_srcpart_index__
> PREHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-08/hr=11
> PREHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-08/hr=12
> PREHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-09/hr=11
> PREHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-09/hr=12
335a383,387
> POSTHOOK: Input: default@default__srcpart_srcpart_index__
> POSTHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-08/hr=11
> POSTHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-08/hr=12
> POSTHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-09/hr=11
> POSTHOOK: Input: default@default__srcpart_srcpart_index__@ds=2008-04-09/hr=12
342a395,442
> 82    val_82
> 82    val_82
> 82    val_82
> 82    val_82
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 83    val_83
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 84    val_84
> 85    val_85
> 85    val_85
> 85    val_85
> 85    val_85
> 86    val_86
> 86    val_86
> 86    val_86
> 86    val_86
> 87    val_87
> 87    val_87
> 87    val_87
> 87    val_87
Standard Error

Begin query: index_auto_mult_tables.q
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Warning: fs.defaultFS is not set when running "chgrp" command.
Warning: fs.defaultFS is not set when running "chmod" command.
Exception: Client Execution results failed with error code = 1
See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
junit.framework.AssertionFailedError: Client Execution results failed with 
error code = 1
See ./ql/target/tmp/log/hive.log or ./itests/qtest/target/tmp/log/hive.log, or 
check ./ql/target/surefire-reports or ./itests/qtest/target/surefire-reports/ 
for specific test cases logs.
        at junit.framework.Assert.fail(Assert.java:57)
        at org.apache.hadoop.hive.ql.QTestUtil.failedDiff(QTestUtil.java:2001)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.runTest(TestCliDriver.java:194)
        at 
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_index_auto_mult_tables(TestCliDriver.java:142)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
        at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
        at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
        at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
        at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
        at 
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
        at 
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124)
        at 
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
        at 
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
        at 
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
Failed query: index_auto_mult_tables.q
{noformat}

>From the output of the failing test, it seems that the index on the srcpart 
>table is not used. 
The hive.log contains the following:
{noformat}
2016-11-07T02:47:45,992  INFO [6401ee51-9d53-4101-a14e-9067d0bc357d main] 
index.IndexWhereProcessor: checking index staleness...
2016-11-07T02:47:45,998  INFO [6401ee51-9d53-4101-a14e-9067d0bc357d main] 
index.IndexWhereProcessor: Index is stale on partition 'ds=2008-04-09/hr=11'. 
Modified time (1478515600000) for 
'pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt'
 is higher than index creation time (1478515599000).
{noformat}

The staleness check fails for the index on the srcpart table for the 
ds=2008-04-09/hr=11 partition, so the index is really not used. The staleness 
check fails, because the modification time of the 
itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt file 
(11:46:40:0) is higher than the index creation time (11:46:39:0).

After some investigation, I found that this happens if the creation of the 
partition folder and moving the kv1.txt file happens when the second turns. So 
the folder is created at 11:46:39,961, but the MoveTask which moves the kv1.txt 
file to the folder starts at 11:46:39:961 and finishes at 11:46:40,012.

{noformat}
2016-11-07T02:46:39,961  INFO [9b9edc01-22c2-460e-b008-03878e74077e main] 
common.FileUtils: Creating directory if it doesn't exist: 
pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11
2016-11-07T02:46:39,973 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: 
{-chgrp,-R,hiveptest,pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09}
2016-11-07T02:46:39,981 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: Return value is :0
2016-11-07T02:46:39,981 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: 
{-chmod,-R,755,pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09}
2016-11-07T02:46:39,992 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: Return value is :0
2016-11-07T02:46:39,992 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
metadata.Hive: The source path is 
/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/data/files/kv1.txt/
 and the destination path is 
/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt/
2016-11-07T02:46:40,001 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: 
{-chgrp,-R,hiveptest,pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt}
2016-11-07T02:46:40,006 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: Return value is :0
2016-11-07T02:46:40,006 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: 
{-chmod,-R,755,pfile:/home/hiveptest/54.215.115.117-hiveptest-0/apache-github-source-source/itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt}
2016-11-07T02:46:40,012 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
shims.HdfsUtils: Return value is :0
2016-11-07T02:46:40,012 DEBUG [9b9edc01-22c2-460e-b008-03878e74077e main] 
log.PerfLogger: </PERFLOG method=FileMoves start=1478515599961 
end=1478515600012 duration=51 from=MoveTask>
{noformat}

In this case, the last modification time of the folder 
itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/ will be 11:46:39 and 
of the kv1.txt will be 11:46:40.

When the index is built in the DDLTask.alterIndex method, the modification time 
which is stored for each partition is the modification time of the folder:
{noformat}
if (baseTbl.isPartitioned()) {
  List<Partition> baseParts;
  if (alterIndex.getSpec() != null) {
    baseParts = db.getPartitions(baseTbl, alterIndex.getSpec());
  } else {
    baseParts = db.getPartitions(baseTbl);
  }
  if (baseParts != null) {
    for (Partition p : baseParts) {
      FileSystem fs = p.getDataLocation().getFileSystem(db.getConf());
      FileStatus fss = fs.getFileStatus(p.getDataLocation());
      basePartTs.put(p.getSpec(), fss.getModificationTime());
    }
  }
} else {
{noformat}

But when the staleness is checked in the IndexUtils.isIndexPartitionFresh 
method, it checks the modification time of the files in the partition folder:
{noformat}
  private static boolean isIndexPartitionFresh(Hive hive, Index index,
      Partition part) throws HiveException {
    LOG.info("checking index staleness...");
    try {
      String indexTs = index.getParameters().get(part.getSpec().toString());
      if (indexTs == null) {
        return false;
      }

      FileSystem partFs = part.getDataLocation().getFileSystem(hive.getConf());
      FileStatus[] parts = partFs.listStatus(part.getDataLocation(), 
FileUtils.HIDDEN_FILES_PATH_FILTER);
      for (FileStatus status : parts) {
        if (status.getModificationTime() > Long.parseLong(indexTs)) {
          LOG.info("Index is stale on partition '" + part.getName()
              + "'. Modified time (" + status.getModificationTime() + ") for '" 
+ status.getPath()
              + "' is higher than index creation time (" + indexTs + ").");
          return false;
        }
      }
    } catch (IOException e) {
      throw new HiveException("Failed to grab timestamp information from 
partition '" + part.getName() + "': " + e.getMessage(), e);
    }
    return true;
  }
{noformat}

Because of the modification time of the 
itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11/kv1.txt file is 
higher (11:46:40), than the modification time of the 
itests/qtest/target/warehouse/srcpart/ds=2008-04-09/hr=11 folder (11:46:39), 
the check fails and the index is not used which leads to the failure of the q 
test.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Reply via email to