Uploaded image for project: 'Kylin'
  1. Kylin
  2. KYLIN-1650

java.io.IOException: Filesystem closed - in Cube Build Step 2 (MapR)

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: v1.5.0, v1.5.1
    • Fix Version/s: v1.5.2
    • Component/s: None
    • Labels:
      None
    • Environment:
      MapR 4.1

      Description

      Hello,

      I am facing error in Build Cube - Step 2 - 4 Reducers are ending with excpetion java.io.IOException: Filesystem closed .... I have searched a lot and tried various versions (1.5.1, 1.5.0 - binary / compiled from sources ...) and always with same result ... all on MapR 4.1 Hadoop

      The problem seems related also to data ... because exactly same cube defined in different Hive schema (DB) - with exactly same metadata - worked fine. BUT trying to the the fact table and lookup table join (one lookup table only) on the Hive tables as defined in the failing Cube Model works fine !!!! So if it is data issue -> then it is strange that select count from fact left outer lookup works without issues ...

      Attaching syslog of one failed reducers ... in case anyone gets an idea what could be the cause of this weird error ...

      Log Type: stderr
      Log Length: 507
      SLF4J: Class path contains multiple SLF4J bindings.
      SLF4J: Found binding in [jar:file:/data/mapr/lib/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
      SLF4J: Found binding in [jar:file:/tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/filecache/10/job.jar/job.jar!/org/slf4j/impl/StaticLoggerBinder.class]
      SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
      SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]

      Log Type: stdout
      Log Length: 304
      spill values to disk...
      create file /kylin/kylin_metadata/kylin-7c7f995d-4925-4fcc-b0bc-c4a97a547c2c/cube_xxxxx_model_150_2ndattempt/fact_distinct_columns/BILLDATE
      append file /kylin/kylin_metadata/kylin-7c7f995d-4925-4fcc-b0bc-c4a97a547c2c/cube_xxxxx_model_150_2ndattempt/fact_distinct_columns/BILLDATE

      Log Type: syslog
      Log Length: 10167
      Showing 4096 bytes of 10167 total. Click here for the full log.
      es from disk
      2016-05-03 18:38:11,275 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: Merging 0 segments, 0 bytes from memory into reduce
      2016-05-03 18:38:11,275 INFO [main] org.apache.hadoop.mapred.Merger: Merging 1 sorted segments
      2016-05-03 18:38:11,279 INFO [main] org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 1 segments left of total size: 8605536 bytes
      2016-05-03 18:38:11,322 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.skip.on is deprecated. Instead, use mapreduce.job.skiprecords
      2016-05-03 18:38:11,342 INFO [main] org.apache.kylin.engine.mr.common.AbstractHadoopJob: The absolute path for meta dir is /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,347 INFO [main] org.apache.kylin.common.KylinConfig: Use KYLIN_CONF=/tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,352 INFO [main] org.apache.kylin.common.KylinConfigBase: Kylin Config was updated with kylin.metadata.url : /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,371 INFO [main] org.apache.kylin.cube.CubeManager: Initializing CubeManager with config /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,376 INFO [main] org.apache.kylin.common.persistence.ResourceStore: Using metadata url /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta for resource store
      2016-05-03 18:38:11,380 WARN [main] org.apache.kylin.common.persistence.ResourceStore: Failed to load ResourceStore impl class: java.lang.NoClassDefFoundError: org/apache/hadoop/hbase/filter/Filter
      2016-05-03 18:38:11,772 INFO [main] org.apache.kylin.cube.CubeDescManager: Initializing CubeDescManager with config /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,772 INFO [main] org.apache.kylin.cube.CubeDescManager: Reloading Cube Metadata from folder /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta/cube_desc
      2016-05-03 18:38:14,530 WARN [main] org.apache.hadoop.mapred.YarnChild: Exception running child : java.io.IOException: Filesystem closed
      at com.mapr.fs.MapRFileSystem.checkOpen(MapRFileSystem.java:1469)
      at com.mapr.fs.MapRFileSystem.lookupClient(MapRFileSystem.java:555)
      at com.mapr.fs.MapRFileSystem.lookupClient(MapRFileSystem.java:649)
      at com.mapr.fs.MapRFileSystem.delete(MapRFileSystem.java:1048)
      at org.apache.hadoop.mapred.Merger$Segment.close(Merger.java:348)
      at org.apache.hadoop.mapred.Merger$MergeQueue.adjustPriorityQueue(Merger.java:521)
      at org.apache.hadoop.mapred.Merger$MergeQueue.next(Merger.java:533)
      at org.apache.hadoop.mapred.ReduceTask$4.next(ReduceTask.java:601)
      at org.apache.hadoop.mapreduce.task.ReduceContextImpl.nextKeyValue(ReduceContextImpl.java:155)
      at org.apache.hadoop.mapreduce.task.ReduceContextImpl.nextKey(ReduceContextImpl.java:121)
      at org.apache.hadoop.mapreduce.lib.reduce.WrappedReducer$Context.nextKey(WrappedReducer.java:302)
      at org.apache.hadoop.mapreduce.Reducer.run(Reducer.java:170)
      at org.apache.hadoop.mapred.ReduceTask.runNewReducer(ReduceTask.java:627)
      at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:389)
      at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:168)
      at java.security.AccessController.doPrivileged(Native Method)
      at javax.security.auth.Subject.doAs(Subject.java:415)
      at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1566)
      at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:163)

      2016-05-03 18:38:14,536 INFO [main] org.apache.hadoop.mapred.Task: Runnning cleanup for the task

      ALSO ADDING FULL SYSLOG:
      =========================

      Log Type: syslog
      Log Length: 10167
      2016-05-03 18:38:05,984 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
      2016-05-03 18:38:05,986 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
      2016-05-03 18:38:06,213 INFO [main] org.apache.hadoop.metrics2.impl.MetricsConfig: loaded properties from hadoop-metrics2.properties
      2016-05-03 18:38:06,314 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: Scheduled snapshot period at 10 second(s).
      2016-05-03 18:38:06,314 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: ReduceTask metrics system started
      2016-05-03 18:38:06,435 INFO [main] org.apache.hadoop.mapred.YarnChild: Executing with tokens:
      2016-05-03 18:38:06,484 INFO [main] org.apache.hadoop.mapred.YarnChild: Kind: mapreduce.job, Service: job_1461856462442_0134, Ident: (org.apache.hadoop.mapreduce.security.token.JobTokenIdentifier@6bb31fae)
      2016-05-03 18:38:06,536 INFO [main] org.apache.hadoop.mapred.YarnChild: Sleeping for 0ms before retrying again. Got null now.
      2016-05-03 18:38:06,842 INFO [main] org.apache.hadoop.mapred.YarnChild: mapreduce.cluster.local.dir for child: /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134
      2016-05-03 18:38:06,999 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
      2016-05-03 18:38:07,000 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
      2016-05-03 18:38:07,481 INFO [main] org.apache.hadoop.mapred.Task: mapOutputFile class: org.apache.hadoop.mapred.MapRFsOutputFile
      2016-05-03 18:38:07,481 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: session.id is deprecated. Instead, use dfs.metrics.session-id
      2016-05-03 18:38:07,521 INFO [main] org.apache.hadoop.mapred.Task: Using ResourceCalculatorProcessTree : [ ]
      2016-05-03 18:38:07,603 INFO [main] org.apache.hadoop.mapred.ReduceTask: Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.DirectShuffle@728cacdc
      2016-05-03 18:38:07,632 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: MergerManager: memoryLimit=1503238528, maxSingleShuffleLimit=375809632, mergeThreshold=992137472, ioSortFactor=256, memToMemMergeOutputsThreshold=256
      2016-05-03 18:38:07,638 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleEventFetcher: attempt_1461856462442_0134_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
      2016-05-03 18:38:07,656 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleEventFetcher: attempt_1461856462442_0134_r_000000_0: Got 1 new map-outputs
      2016-05-03 18:38:07,685 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,692 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,693 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,695 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,696 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,697 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,698 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,699 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,700 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,702 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,703 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,705 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,767 INFO [MapOutputCopier task_1461856462442_0134_r_000000.0] org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.snappy]
      2016-05-03 18:38:07,770 INFO [MapOutputCopier task_1461856462442_0134_r_000000.0] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleFetcher: fetcher#0 about to shuffle output of map attempt_1461856462442_0134_m_000000_0 to MEMORY
      2016-05-03 18:38:08,046 INFO [MapOutputCopier task_1461856462442_0134_r_000000.0] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: closeInMemoryFile -> map-output of size: 52779014, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->52779014
      2016-05-03 18:38:08,047 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleEventFetcher: EventFetcher is interrupted.. Returning
      2016-05-03 18:38:08,141 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
      2016-05-03 18:38:08,151 INFO [main] org.apache.hadoop.mapred.Merger: Merging 1 sorted segments
      2016-05-03 18:38:08,152 INFO [main] org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 1 segments left of total size: 52778982 bytes
      2016-05-03 18:38:08,160 INFO [main] org.apache.hadoop.io.compress.CodecPool: Got brand-new compressor [.snappy]
      2016-05-03 18:38:11,273 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: Merged 1 segments, 52779014 bytes to disk to satisfy reduce memory limit
      2016-05-03 18:38:11,274 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: Merging 1 files, 8644203 bytes from disk
      2016-05-03 18:38:11,275 INFO [main] org.apache.hadoop.mapreduce.task.reduce.DirectShuffleMergeManagerImpl: Merging 0 segments, 0 bytes from memory into reduce
      2016-05-03 18:38:11,275 INFO [main] org.apache.hadoop.mapred.Merger: Merging 1 sorted segments
      2016-05-03 18:38:11,279 INFO [main] org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 1 segments left of total size: 8605536 bytes
      2016-05-03 18:38:11,322 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.skip.on is deprecated. Instead, use mapreduce.job.skiprecords
      2016-05-03 18:38:11,342 INFO [main] org.apache.kylin.engine.mr.common.AbstractHadoopJob: The absolute path for meta dir is /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,347 INFO [main] org.apache.kylin.common.KylinConfig: Use KYLIN_CONF=/tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,352 INFO [main] org.apache.kylin.common.KylinConfigBase: Kylin Config was updated with kylin.metadata.url : /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,371 INFO [main] org.apache.kylin.cube.CubeManager: Initializing CubeManager with config /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,376 INFO [main] org.apache.kylin.common.persistence.ResourceStore: Using metadata url /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta for resource store
      2016-05-03 18:38:11,380 WARN [main] org.apache.kylin.common.persistence.ResourceStore: Failed to load ResourceStore impl class: java.lang.NoClassDefFoundError: org/apache/hadoop/hbase/filter/Filter
      2016-05-03 18:38:11,772 INFO [main] org.apache.kylin.cube.CubeDescManager: Initializing CubeDescManager with config /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta
      2016-05-03 18:38:11,772 INFO [main] org.apache.kylin.cube.CubeDescManager: Reloading Cube Metadata from folder /tmp/hadoop-mapr/nm-local-dir/usercache/mapr/appcache/application_1461856462442_0134/container_1461856462442_0134_01_000003/meta/cube_desc
      2016-05-03 18:38:14,530 WARN [main] org.apache.hadoop.mapred.YarnChild: Exception running child : java.io.IOException: Filesystem closed
      at com.mapr.fs.MapRFileSystem.checkOpen(MapRFileSystem.java:1469)
      at com.mapr.fs.MapRFileSystem.lookupClient(MapRFileSystem.java:555)
      at com.mapr.fs.MapRFileSystem.lookupClient(MapRFileSystem.java:649)
      at com.mapr.fs.MapRFileSystem.delete(MapRFileSystem.java:1048)
      at org.apache.hadoop.mapred.Merger$Segment.close(Merger.java:348)
      at org.apache.hadoop.mapred.Merger$MergeQueue.adjustPriorityQueue(Merger.java:521)
      at org.apache.hadoop.mapred.Merger$MergeQueue.next(Merger.java:533)
      at org.apache.hadoop.mapred.ReduceTask$4.next(ReduceTask.java:601)
      at org.apache.hadoop.mapreduce.task.ReduceContextImpl.nextKeyValue(ReduceContextImpl.java:155)
      at org.apache.hadoop.mapreduce.task.ReduceContextImpl.nextKey(ReduceContextImpl.java:121)
      at org.apache.hadoop.mapreduce.lib.reduce.WrappedReducer$Context.nextKey(WrappedReducer.java:302)
      at org.apache.hadoop.mapreduce.Reducer.run(Reducer.java:170)
      at org.apache.hadoop.mapred.ReduceTask.runNewReducer(ReduceTask.java:627)
      at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:389)
      at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:168)
      at java.security.AccessController.doPrivileged(Native Method)
      at javax.security.auth.Subject.doAs(Subject.java:415)
      at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1566)
      at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:163)

      2016-05-03 18:38:14,536 INFO [main] org.apache.hadoop.mapred.Task: Runnning cleanup for the task

        Attachments

          Activity

            People

            • Assignee:
              shaofengshi Shao Feng Shi
              Reporter:
              calaba@gmail.com Richard Calaba
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: