Recordings show when control is transferred into a thread by an ExecutorService

[apotterri]

Currently, if an HTTP endpoint (e.g. a Spring Controller) uses an ExecutorService to run a task, none of that processing shows up in the AppMap. For example:

  @DeleteMapping("dolphins")
  public String dolphins() throws ExecutionException, InterruptedException {
    ExecutorService executorService = Executors.newCachedThreadPool();
    Future<Object> future1 = executorService.submit((Callable<Object>)() -> {
      DolphinChat dc = new DolphinChat();
      dc.say("So");
      dc.say("long,");
    });
    Future<Object> future2 = executorService.submit((Callable<Object>)() -> {
      DolphinChat dc = new DolphinChat();
      dc.say("and thanks for");
      dc.say("all the fish");
    });

    NextUp nu = new NextUp();
    nu.say("Mostly Harmless");

    return future1.get() + " " + future2.get();
  }

the calls to DolphinChat methods won't show up in the AppMap.

Instead, the (pseudo) events should look like this:

{http_server_request, thread: 1}
  {call, method: ExecutorService.submit, thread:1}
    {call, method: Runnable.run, thread: 1, task:true}
      {call, method: DolphinChat.say("So"), thread: 1}
      {return, parent: DolphinChat.say, thread: 1}
      {call, method: DolphinChat.say("long"), thread: 1}
      {return, parent: DolphinChat.say, thread: 1}
    {return, parent:Runnable.run, thread: 1}
  {return, parent: ExecutorService.submit, thread: 1} // when get is called on the Future returned by submit
  {call, method: ExecutorService.submit, thread:1}
    {call, method: Runnable.run, thread: 1, task:true}
      {call, method: DolphinChat.say("and thanks for"), thread: 1}
      {return, parent: DolphinChat.say, thread: 1}
      {call, method: DolphinChat.say("all the fish"), thread: 1}
      {return, parent: DolphinChat.say, thread: 1}
    {return, parent:Runnable.run, thread: 1}
  {return, parent: ExecutorService.submit, thread: 1} // when get is called on the Future returned by submit
  {call, method: NextUp.say("Mostly Harmless"), thread: 1}
  {return, parent: NextUp.say, thread: 1}
{http_server_response, thread: 1}

This says they all have the same thread id (that matches the thread that creates the ExecutorService). The ordering of the call and return events show that the calls to DolphinChat.say happened in a Runnable/Callable submitted to an ExecutorService. Note that the order of the complete Runnable.run call chains may not match the order in the code, of course, because they were run on separate threads.

Test cases:

• end-to-end, for an endpoint like dolphins, generates an AppMap
• checkpoint is disabled once ExecutorService.submit has been called
• classes referenced only in a task show up in the classmap of the final AppMap
• both a Callable and Runnable passed to ExecutorService.submit are handled correctly
• process recording for a call to dolphins generates an AppMap
• remote recording that spans a call to the dolphins endpoint generates an AppMap
• task recording stops when Future.cancel is called. [What should happen to the task's recording?]
• task recording stops when the method that called ExecutorService.submit returns. [What should happen if there are outstanding Futures?]

[jansorg]

@apotterri Is this for the JetBrains plugin or for https://github.com/getappmap/appmap-java?

[apotterri]

Oops, sorry.

[dividedmind]

FWIW, I think it is the best we can do with the current AppMap spec while maintaining coherent UX, even if the data thus generated isn't technically 100% accurate (esp. re. event ordering and thread IDs).

[apotterri]

I investigated the current agent a little more, to see how it handles code that uses an ExecutorService. (This is my original example, updated so it compiles, and allows comparison of implementations.)

    @DeleteMapping("dolphins")
    public String dolphins() throws Exception {
      ExecutorService executorService = Executors.newCachedThreadPool();
      if (true) {
        Future<Object> future1 = executorService.submit((Callable<Object>) () -> {
          DolphinChat dc1 = new DolphinChat();
          return dc1.say("So") + dc1.say("long,");
        });
        Future<Object> future2 = executorService.submit((Callable<Object>) () -> {
          DolphinChat dc2 = new DolphinChat();
          return dc2.say("and thanks for") + dc2.say("all the fish");
        });
        System.out.println(future1.get() + " " + (String) future2.get());
      } else {
        Supplier<String> future1 = () -> {
          DolphinChat dc1 = new DolphinChat();
          return dc1.say("So") + dc1.say("long,");
        };
        Supplier<String> future2 = () -> {
          DolphinChat dc2 = new DolphinChat();
          return dc2.say("and thanks for") + dc2.say("all the fish");
        };
        System.out.println(future1.get() + " " + (String) future2.get());
      }
      NextUp nu = new NextUp();
      nu.say("Mostly Harmless");

      return "deleted";
    }

When run with process or remote recording, this code produces this sequence diagram:

Changing

      if (true) {

to

      if (false) {

i.e. running without an ExecutorService, you get this sequence diagram:

However, in both cases, events for the calls to DolphinChat and DolphinChatImpl methods appear in the AppMaps. When running with the ExecutorService, however, the thread_id in those events different from the thread_id for the http_server_request (of course), so they don't show up in the sequence diagrams.

[kgilpin]

Do you have Limit Root events to HTTP checked?

[dividedmind]

• task recording stops when the method that called ExecutorService.submit returns. [What should happen if there are outstanding Futures?]

In appmap-node, a similar case (outstanding promises when recording ends) would show up in an AppMap as a Promise with value: "Promise { pending }", which is detected by the unfulfilled promises scanner and usually indicates a bug. Perhaps something similar could be done here to enable similar detection.