presto 上线430版本遇到的问题总结

曾伟展
1,784 阅读2分钟

起因

公司使用了icebery存储数据，presto作为提供给用户查询的引擎，当前使用的版本对icebery支持较弱，存在读parquet异常问题，需要将版本升级到430。

合并代码

老版本我们当时为了支持hive的视图功能，以及其他一些功能，在原来版本的基础上做了一些代码更改，原本是我想两个版本库的代码直接合并的，后面灵哥跟我说，你可以直接使用git rebase 的功能，讲自己更改的代码有选择的合并到当前的最新分支上。这是一个及其好用的工具，特别是我们这种，对于开源的代码更改不多，同时也希望可以跟着社区升级的。

上线不顺利

当我把patch打回去，编译好代码，觉得万事俱备，JDK也改为11，可以准备上线，我在测试环境部署了新版本的presto，事情没有想象中的顺利，worker 起不来..我们是使用yarn来部署presto的worker的，presto-server是安全无恙的，但是worker起不来，我把yarn上的日志拿下来之后，发现报了如下异常：

...skipping...
        at io.prestosql.plugin.hive.HiveConnectorFactory.create(HiveConnectorFactory.java:63)
        at io.prestosql.connector.ConnectorManager.createConnector(ConnectorManager.java:349)
        at io.prestosql.connector.ConnectorManager.createCatalog(ConnectorManager.java:208)
        at io.prestosql.connector.ConnectorManager.createCatalog(ConnectorManager.java:200)
        at io.prestosql.connector.ConnectorManager.createCatalog(ConnectorManager.java:186)
        at io.prestosql.metadata.StaticCatalogStore.loadCatalog(StaticCatalogStore.java:88)
        at io.prestosql.metadata.StaticCatalogStore.loadCatalogs(StaticCatalogStore.java:68)
        at io.prestosql.server.Server.doStart(Server.java:117)
        at io.prestosql.server.Server.lambda$start$0(Server.java:72)

        at io.prestosql.$gen.Presto_340_2_g0416013_dirty____20200817_055536_1.run(Unknown Source)
        at io.prestosql.server.Server.start(Server.java:72)
        at io.prestosql.server.PrestoServer.main(PrestoServer.java:38)

Caused by: java.lang.RuntimeException: failed to load Hadoop native library
        at io.prestosql.hadoop.HadoopNative.requireHadoopNative(HadoopNative.java:59)
        at io.prestosql.plugin.hive.HdfsEnvironment.<clinit>(HdfsEnvironment.java:39)
        ... 52 more
Caused by: java.lang.RuntimeException: native snappy library not available: SnappyCompressor has not been loaded.
        at org.apache.hadoop.io.compress.SnappyCodec.checkNativeCodeLoaded(SnappyCodec.java:72)
        at org.apache.hadoop.io.compress.SnappyCodec.getDecompressorType(SnappyCodec.java:195)
        at io.prestosql.hadoop.HadoopNative.loadAllCodecs(HadoopNative.java:72)
        at io.prestosql.hadoop.HadoopNative.requireHadoopNative(HadoopNative.java:53)
        ... 53 more

native snappy library not available: SnappyCompressor has not been loaded

怎么会出现这个异常呢？

此时此刻我出现了一千万个问号，presto跟其他项目最大的不同在于，presto几乎把他所依赖项目都自己实现，例如hive connector中依赖的hadoop，用的就是presto-hadoop-apache 项目。

从异常上看，就是夹在native包有问题，第一个反应是去看一下代码，跟踪到了可能问题出现在这段代码

public final class NativeCodeLoader {

  private static final Logger LOG =
      LoggerFactory.getLogger(NativeCodeLoader.class);
  
  private static boolean nativeCodeLoaded = false;
  
  static {
    // Try to load native hadoop library and set fallback flag appropriately
    if(LOG.isDebugEnabled()) {
      LOG.debug("Trying to load the custom-built native-hadoop library...");
    }
    try {
      System.loadLibrary("hadoop");
      LOG.debug("Loaded the native-hadoop library");
      nativeCodeLoaded = true;
    } catch (Throwable t) {
      // Ignore failure to load
      if(LOG.isDebugEnabled()) {
        LOG.debug("Failed to load native-hadoop with error: " + t);
        LOG.debug("java.library.path=" +
            System.getProperty("java.library.path"));
      }
    }
    
    if (!nativeCodeLoaded) {
      LOG.warn("Unable to load native-hadoop library for your platform... " +
               "using builtin-java classes where applicable");
    }
  }

这里只要打开debug日志，就可以看到为什么会出现load snappy有问题的情况了，于是，我按照官网，在/etc/下新增配置文件log.properties，重启，见证奇迹的那一刻到了！

io.prestosql=DEBUG
org.apache.hadoop=DEBUG

然后，现实给我重重的一击，没有打印出来org.apache.hadoop的DEBUG日志，但是io.prestosql的DEBUG日志有的，怎么回事？为什么会这样呢？

在尝试了在jvm的启动参数新增log4j的配置文件没有效果之后，不得不去社区问一下，如何才能新增DEBUG日志，社区还是牛人多，有人给我贴了一个链接：github.com/prestosql/p…

他们也是有这个需求，打开hadoop相关的DEBUG日志，但是社区在最新的版本因为考虑到了输出的日志比较多，就把日志关闭了，如果想要开启的话，可以自己更改一下pom.xml编译。

好吧！白折腾了一下下午，改一下配置，重新编译！

		<dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-jdk14</artifactId>
            <version>${dep.slf4j.version}</version>
            <scope>runtime</scope>
        </dependency>

日志

经历了一个下午的折腾，晚上终于把日志打出来了

2020-08-19T20:11:18.537+0800    DEBUG   main    org.apache.hadoop.util.NativeCodeLoader Trying to load the custom-built native-hadoop library...
2020-08-19T20:11:18.538+0800    DEBUG   main    org.apache.hadoop.util.NativeCodeLoader Failed to load native-hadoop with error: java.lang.UnsatisfiedLinkError: Native Library /opt/c
loudera/parcels/CDH-XX/lib/hadoop/lib/native/libhadoop.so.1.0.0 already loaded in another classloader

通过日志，我们发现presto的worker在启动的时候会把系统当中的native包load到内存里面，跟presto的hadoop包里面的resouce里面自带的native冲突到了，导致进程无法启动。同时我看到了有人也出现过这个问题，app.slack.com/client/TFKP… 不得不说，社区真是宝藏。

原因

为什么worker启动的时候会把系统本地的native包的路径带进去呢？通过阿里提供的工具arthas，我们发现在nodemanger启动我们的worker的时候，会通过LD_LIBRARY_PATH 这个参数把系统参数传递到子进程。

明白了原因，解决方式也比较简单，就是在启动worker的时候，将LD_LIBRARY_PATH设置为空就可以了。

终于搞定。

总结

  1. 社区是一个好东西，遇到的问题可以先去slack先查询
  2. 要善于利用工具
  3. 对整个运行机制还不够熟悉，还需要多刻意练习。
avatar
文章
阅读
粉丝