Google Pub/Sub 消息大约需要 5 分钟才能发布。这是为啥？

Posted 2023-02-16

【中文标题】Google Pub/Sub 消息大约需要 5 分钟才能发布。这是为啥？

【英文标题】：Google Pub/Sub message took ~5 minutes to be published. Why is that?Google Pub/Sub 消息大约需要 5 分钟才能发布。这是为什么？

【发布时间】：2021-06-17 16:04:18

【问题描述】：

我有一个正在发布 Cloud Pub/Sub 消息的 Cloud Functions。但是，此测试消息需要大约 5 分钟才能发布并由测试订阅使用。

这是正常的时机吗？我实际上期望它会更快，让我们说更具响应性。当我的 Auth0 挂钩（注册后）触发 Cloud Function 端点时，我想在我的数据库中初始化一个用户。

最好的情况是用户初始化应该发生在用户注册后访问网站之前，因此速度有点关键。

这里是函数代码（Java）：

public class UserInit implements HttpFunction 
  @Override
  public void service(HttpRequest request, HttpResponse response) throws Exception 
    String projectId = "app-platform";
    String topicId = "user-init";
    final TopicName topicName = TopicName.of(projectId, topicId);
    final Publisher publisher = Publisher.newBuilder(topicName).build();
    System.out.println("project: " + projectId);
    System.out.println("topic: " + topicId);
    final PubsubMessage message = PubsubMessage.newBuilder()
        .putAttributes("test", "test")
        .build();
    final ApiFuture<String> messageIdFuture = publisher.publish(message);
    ApiFutures.addCallback(messageIdFuture, new ApiFutureCallback<String>() 
      public void onSuccess(String messageId) 
        System.out.println("published with message id: " + messageId);
      

      public void onFailure(Throwable t) 
        System.out.println("failed to publish: " + t);
      
    , MoreExecutors.directExecutor());
  

以下是相关日志：

2021-03-20T12:29:47.486387599Zuser-initlo8xln5ztgq3 Function execution started
2021-03-20T12:29:57.947Zuser-initlo8xln5ztgq3 project: app-platform
2021-03-20T12:29:57.949Zuser-initlo8xln5ztgq3 topic: user-init
2021-03-20T12:29:59.551220278Zuser-initlo8xln5ztgq3 Function execution took 12065 ms, finished with status code: 200
2021-03-20T12:35:13.145Zuser-initlo8xln5ztgq3 published with message id: 2139319306781573

第一件事是Function execution took 12065 ms，这让我很惊讶。该函数的执行耗时 12 秒。恕我直言，那是相当长的一段时间。 然而，真正烦人的是函数执行和 Pub/Sub 回调之间的时间

2021-03-20T12:29:59 // execution
2021-03-20T12:35:13 // callback print message

这是大约 5 分钟过去了。我可以通过 Pub/Sub 监控以及我的测试订阅来确认这一点，在我预期消息已经发布后，我多次执行“拉取”。在所有情况下，我都可以确认，从函数执行到发现 pub/sub 消息的时间已经提到了大约 5 分钟。

所以我想知道这是预期的行为吗？我很惊讶，因为我第一次使用 Pub/Sub，或者我是对的，这里有些奇怪？

这也是我的cloudbuild.yaml 设置以及我的功能配置：

steps:
  - name: 'gcr.io/google.com/cloudsdktool/cloud-sdk'
    args:
      - gcloud
      - functions
      - deploy
      - user-init
      - --runtime=java11
      - --region=europe-west3
      - --source=./user-init
      - --entry-point=com.app.functions.UserInit
      - --allow-unauthenticated
      - --trigger-http
  - name: 'gcr.io/google.com/cloudsdktool/cloud-sdk'
    args:
      - gcloud
      - alpha
      - functions
      - add-iam-policy-binding
      - user-init
      - --region=europe-west3
      - --member=allUsers
      - --role=roles/cloudfunctions.invoker

编辑 1

我尝试在publish() 调用之后等待与.wait() 的并发任务。

相关更改如下所示：

    final Publisher publisher = Publisher.newBuilder(topicName)
        .setBatchingSettings(Publisher.Builder.getDefaultBatchingSettings())
        .build();
    final PubsubMessage message = PubsubMessage.newBuilder()
        .putAttributes("test", "test")
        .build();
    publisher.publish(message).wait();

但是这些错误是由于使用wait()而发生的

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at java.base/java.lang.Thread.run(Thread.java:834)
at com.google.cloud.functions.invoker.runner.Invoker$NotFoundHandler.handle(Invoker.java:392)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)

【问题讨论】：

关于“功能需要 12 秒才能完成”...我相信该消息是由 Cloud Functions 记录的。两个直接的想法（猜测）浮现在脑海中……第一个是您可能经历过冷启动延迟。这 12 秒可能包括启动 JVM、初始化框架和调用函数的时间。第二个想法是不允许你在后台工作。对 ApiFutureCallback 不熟悉...但是您是否期待在从 Cloud Function 入口点返回后执行的工作？

@Kolban 不，我不想将任何业务逻辑放入回调中。我只是使用 ApiFunctionCallback 来了解函数发布消息之前的时间

@Kolban 我觉得这 12 秒没问题 - 也许我可以改用 python 脚本来加快速度。但是我不喜欢的是消息发布的约 5 分钟

【参考方案1】：

您的 Cloud Functions 真正在 12 秒内执行完毕，并回复了 HTTP 200 代码。然后 CPU 会受到限制，因为在请求处理之外，您的 Cloud Functions 不需要 CPU。

您的 Cloud Functions 允许使用的 CPU 不到 5%，非常少，而且使用这么少的 CPU 执行回调需要时间。

确实，您在等待有效消息发布之前回复 HTTP 200。在函数末尾添加这一行

messageIdFuture.wait();

等待并发线程结束。你会发现它会更有效率！

---

您还需要知道Cloud Functions performance (and thus pricing) depends on the quantity of memory。默认情况下，您有 256Mb 的内存 -> 400Mhz 的计算处理：仅使用 400Mhz 单核 CPU 启动 Cloud Functions + JVM 确实需要时间（12 秒）。而且你也可以理解，其中 5% 来处理回调，可能需要几分钟！

因此，增加 Cloud Functions 内存以提高 Cloud Functions 性能

【讨论】：

感谢您的提示。我根据您的建议编辑了我的问题。我将内存增加到 4096MB，并在发布例程的末尾添加了 .wait() 方法。不幸的是，由于该更改发生了错误。我很难公平地解释这一点