[Driver] Added process information to emitted task messages #16444

BenchR267 · 2018-05-08T17:21:21Z

When providing the -parseable-output flag to the swift compiler, it will provide json formatted messages about tasks that run.
I added some optional metrics in form of user time, system time and maxrss to the output. This can be used by other tools using the compiler to get some insights about time and memory usage.

rdar://39798231

BenchR267 · 2018-05-14T17:19:51Z

@swift-ci please smoke test

graydon · 2018-05-14T19:52:22Z

@BenchR267 I'm not sure about this; we already gather and emit this information in JSON in the statistics-reporting subsystem (i.e. when you run with --stats-output-dir). Is that inadequate for your needs?

jrose-apple · 2018-05-14T20:33:20Z

We definitely don't want Xcode or other external tools depending on the format from -stats-output-dir, do we?

BenchR267 · 2018-05-14T23:14:54Z

An advantage of having this information in the driver output is also that it's bundled to the finish message which is emitted when the sub-process finishes, not the whole driver invocation.

jrose-apple · 2018-05-14T23:17:40Z

^ That part's less useful until we have a way to identify which "jobs" were actually from the same process.

BenchR267 · 2018-05-14T23:22:42Z

What do you mean by that? The measured and emitted information in this PR are always bound to a process. Do you mean that a process could fulfill multiple jobs?
I think that wouldn't be a deal breaker for the metrics output since that clearly relates to the process, not a job.

graydon · 2018-05-15T05:04:38Z

@BenchR267 The callbacks that come out of the task queue are process events. Those processes no longer correspond 1:1 to emitFinishedMessage calls; instead (as of #16492) if a batch process that combined (say) 100 jobs exits, we make 100 calls to emitFinishedMessage, one for each job that was combined into the batch. So if you were to pass the batch process metrics to every one of those emitFinishedMessage calls and print the same metrics for each sub-job out to the stream, you'd be very seriously overstating the elapsed time to anyone listening to that message stream.

(This is a compromise around how best to represent the sub-jobs within a batch process that is compiling multiple files. We had to choose something, and this seems like the most congruent with the way Xcode thinks about subtasks of the driver.)

BenchR267 · 2018-05-15T17:26:25Z

Ah, I see. So if a process is processing 5 different Swift files, I get 5 begin and 5 end messages (if all succeed) but each one has all input and output files in it. The only difference is that only one of them has a real PID (positive) and all others have quasi-PIDs?
I'm not sure I understand why this was fixed like that but a solution for my change here could be to only include the metrics for 'real PIDs' couldn't it? The client could then ignore the quasi-PIDs if he is only interested in the process metrics.

graydon · 2018-05-15T17:32:20Z

@BenchR267 No, none of them has a real PID. We only send messages about the quasi-PIDs, in order to avoid confusing consumers who think that the message stream is one-process-per-output.

davidungar

Nice start, but ydou'll want to check with @graydon about overlap of functionality. He's already added much of this functionality in a different way.

davidungar · 2018-05-15T19:58:35Z

include/swift/Basic/TaskQueue.h

@@ -39,6 +41,43 @@ enum class TaskFinishedResponse {
  StopExecution,
 };

+/// Define basic metrics about tasks that ran
+struct TaskFinishedMetrics {


I would like to see a bit in this comment about what the metrics will be used for, what code will consume them, etc.

Also (nitpick, in the Jordan sense), the name TaskFinishedMetrics seems not quite write in two respects:

These are only times, and

These are not about the finishing, they are about the whole task.
So, how about TaskTimes?

Thanks for the review! Sorry, I just changed the structure a bit to react to @graydon s recent changes. This does now also contains the real pid (which is not emitted if jobs are batched otherwise). The Metrics struct does not only contain times (maxrss is also part of it) but I agree that another name might be a better fit.
What about Stats or Usage or ResourceUsage?

davidungar · 2018-05-15T20:09:55Z

include/swift/Basic/TaskQueue.h

@@ -81,13 +120,15 @@ class TaskQueue {
  /// \param Errors the errors from the task which finished execution, if
  /// available and SeparateErrors was true.  (This may not be available on all
  /// platforms.)
+  /// \param Metrics define basic metrics about the task that ran (has no value
+  /// if no separate process)


Nitpick: "define" seems like the wrong word here. The parameter isn't defining which metrics are provided, rather it is supplying the values for the metrics.
The parenthetical comment deserves more prominence.
Something like: "If the task ran as a separate process, Metrics supplies the values for the times in took."

You're right, I changed the description.

davidungar · 2018-05-15T20:10:59Z

include/swift/Basic/TaskQueue.h

@@ -100,16 +141,19 @@ class TaskQueue {
  /// \param Errors the errors from the task which exited abnormally, if
  /// available and SeparateErrors was true.  (This may not be available on all
  /// platforms.)
+  /// \param Metrics define basic metrics about the task that ran (has no value


Seem comment above.

davidungar · 2018-05-15T20:13:16Z

lib/Basic/TaskQueue.cpp

@@ -85,8 +85,8 @@ bool DummyTaskQueue::execute(TaskQueue::TaskBeganCallback Began,
      std::string Output = "Output placeholder\n";
      std::string Errors =
          P.second->SeparateErrors ? "Error placeholder\n" : "";
-      if (Finished(P.first, 0, Output, Errors, P.second->Context) ==
-          TaskFinishedResponse::StopExecution)
+      if (Finished(P.first, 0, Output, Errors, Optional<TaskFinishedMetrics>(),


Will None work instead of Optional<TaskFinishedMetrics>?

Yes, None is much better. I just learned about llvm::Optional, wanted to use a nullptr before 🙈 Btw: is there a map operation on Optional?

davidungar · 2018-05-15T20:14:20Z

lib/Basic/Unix/TaskQueue.inc

-static Optional<int> waitForPid(const pid_t pidToWaitFor);
+
+/**
+ Wait for a process with a given pid to finish.


Nitpick: should be "Wait for the process"

davidungar · 2018-05-15T20:18:33Z

lib/Basic/Unix/TaskQueue.inc

@@ -555,34 +562,36 @@ static bool
 cleanUpAHungUpTask(Task &T,
                   const TaskQueue::TaskFinishedCallback FinishedCallback,
                   const TaskQueue::TaskSignalledCallback SignalledCallback) {
-  const Optional<int> StatusIfOK = waitForPid(T.getPid());
-  if (!StatusIfOK)
+  const auto StatusIfOK = waitForPid(T.getPid());


Please rename StatusIfOK to StatusAndTimes (assuming you change the Metrics class name to Times). Or rename to StatusAndMetrics.

davidungar · 2018-05-15T20:21:16Z

lib/Basic/Unix/TaskQueue.inc

                   : false /* Can this case ever happen? */;
 }

-static Optional<int> waitForPid(const pid_t pidToWaitFor) {
+static std::pair<Optional<int>, Optional<TaskFinishedMetrics>> waitForPid(const pid_t pidToWaitFor) {


Right now, you have waitForPid returning two optionals, but only two of the four possible cases can ever occur. If I'm right, it should be returning an optional pair, not a pair of optionals.

It was an optional status before, that's why I chose to keep the status optional.

Much better!

davidungar · 2018-05-15T20:24:53Z

lib/Driver/Driver.cpp

+                              OI.SDKPath = output.str();
+                          }
+                          return sys::TaskFinishedResponse::ContinueExecution;
+                        });


lines 1429-1440 seem to show that they were reindented. Is this what git-clang-format did? (Folks here like to use git-clang-format to keep formatting stable across changes.)

I used git-clang-format over all changes, so probably it wasn't stable before ¯\(ツ)/¯

(But I still reverted the change to keep it as small as possible)

Sigh... Thanks.

davidungar · 2018-05-15T20:26:08Z

lib/Driver/ParseableOutput.cpp

@@ -180,24 +181,29 @@ class BeganMessage : public DetailedCommandBasedMessage {

 class TaskOutputMessage : public TaskBasedMessage {
  std::string Output;
+  Optional<sys::TaskFinishedMetrics> Metrics;


You'll want to check with @graydon about overlap of functionality. He's already added much of this functionality in a different way.

BenchR267 · 2018-05-15T21:51:34Z

@graydon @davidungar Thanks for your input! I reworked on this patch and changed it so the output does contain the "real" pid as well so the client could know which jobs ran in one batch/process. I added this information to begin, finished and signalled messages while only finished and signalled may contain resource usage (thanks for the lead to a better name @davidungar).
Looking forward to see what you think about this! If it's a re-implementation of an existing feature, could you please give me hint where to find it / how to use it? Thanks in advance!

jakepetroules · 2018-05-15T22:02:17Z

docs/DriverParseableOutput.rst


 Example::

   {
     "kind": "began",
     "name": "compile",
     "pid": 12345,
+     "process": {
+       "real_pid": 38732


Isn't this impossible? From reading the documentation I inferred that the following must hold:

pid == process.real_pid || pid < 0

If so, please update the example.

Oh sure, you're right! I should also add that this will match the pid value if pid > 0 to the documentation!

Excellent, thanks!

Thanks for finding this! 👍🏻

jakepetroules · 2018-05-15T22:02:39Z

docs/DriverParseableOutput.rst

-     "exit-status": 0
+     "exit-status": 0,
+     "process": {
+       "real_pid": 31232,


jakepetroules · 2018-05-15T22:02:46Z

docs/DriverParseableOutput.rst

-     "signal": 4
+     "signal": 4,
+     "process": {
+       "real_pid": 31232,


BenchR267 · 2018-05-16T18:54:35Z

@swift-ci please smoke test

graydon

This looks basically ok, modulo a bunch of changes for portability and such (noted inline). I would also ask that you test it with some older Xcodes (at least 9.3) in both new and old build systems, to be sure that it doesn't break them.

graydon · 2018-05-15T22:03:11Z

include/swift/Basic/TaskQueue.h

+                                   uint64_t(Usage.ru_utime.tv_usec),
+                               uint64_t(Usage.ru_stime.tv_sec) * 1000000 +
+                                   uint64_t(Usage.ru_stime.tv_usec),
+                               Usage.ru_maxrss) {}


This is, unfortunately, a count of bytes rather than KB on macOS. See https://github.com/apple/swift/blob/master/lib/Basic/Statistic.cpp#L43-L60 for conditional form.

Oh noes 🤦‍♂️

graydon · 2018-05-16T19:13:07Z

include/swift/Basic/TaskQueue.h

  /// \param Context the context which was passed when the task was added
  ///
  /// \returns true if further execution of tasks should stop,
  /// false if execution should continue
  using TaskFinishedCallback = std::function<TaskFinishedResponse(
      ProcessId Pid, int ReturnCode, StringRef Output, StringRef Errors,
-      void *Context)>;
+      TaskProcessInformation Process, void *Context)>;


Minor preference for calling this variable ProcInfo or something; it's not a process in the sense of being a handle or something, just auxiliary information.

That makes sense 👍🏻 ProcInfo is a good idea

graydon · 2018-05-16T19:20:49Z

include/swift/Basic/TaskQueue.h

@@ -21,6 +22,7 @@
 #include <functional>
 #include <memory>
 #include <queue>
+#include <sys/resource.h>


This should not be in include/swift/Basic/TaskQueue.h; that file covers all platform task queues, including those non-unix / without-rusage. Instead, it should be in the lib/Basic/Unix/TaskQueue.inc unix-specific include fragment, and the code that includes this should be guarded by #ifdef HAVE_SYS_RESOURCE_H, and the code that instantiates struct rusage should be guarded by #if defined(HAVE_GETRUSAGE) && !defined(__HAIKU__)

See the rusage-extracting code in lib/Basic/Statistic.cpp for example (also for the apple-specific bytes-vs-kb bit).

It seems like the import isn't needed at all. It's at least building (incremental and clean) without it.

graydon · 2018-05-16T19:35:14Z

lib/Basic/Unix/TaskQueue.inc

  for (;;) {
    int Status = 0;
-    const pid_t pidFromWait = waitpid(pidToWaitFor, &Status, 0);
+    struct rusage Usage;


The wait4 call isn't POSIX, it's mostly-standard on anything BSD-compat but it should probably be conditionalized. I suspect it's safe to hang this on the HAVE_GETRUSAGE probe already done over in LLVM, but it's a bit indirect; maybe add a specific check_symbol_exists(wait4, "sys/wait.h", HAVE_WAIT4) probe to swift's CMakeLists.txt?

Yes, that's a good idea. If wait4 is not available, I just fallback to waitpid and return None usage. Just need to find out how that cmake definitions work :)

I tried different configurations but it didn't worked out like I expected. I added check_symbol_exists(wait4 "sys/wait.h" HAVE_WAIT4) to the CMakeLists.txt and expected that I can check with #if defined(HAVE_WAIT4) in the code but it didn't work (it evaluated to false while wait4 should be there on my system.
Could you please give me a hint?

Thanks for your help offline, I added the check-symbol to the cmakelist.

davidungar

"is there a map operation on Optional?" Good question! I don't know about one. Let me know what you find out!

davidungar · 2018-05-15T20:27:14Z

lib/Driver/ParseableOutput.cpp

-                                           int ExitStatus, StringRef Output) {
-  FinishedMessage msg(Cmd, Pid, Output, ExitStatus);
+void parseable_output::emitFinishedMessage(
+    raw_ostream &os, const Job &Cmd, int64_t Pid, int ExitStatus,


Is this git-clang-format indenting?

davidungar · 2018-05-15T20:28:16Z

lib/Driver/ParseableOutput.cpp

-                                    ExitStatus(ExitStatus) {}
+                  Optional<sys::TaskFinishedMetrics> Metrics, int ExitStatus)
+      : TaskOutputMessage("finished", Cmd, Pid, Output, Metrics),
+        ExitStatus(ExitStatus) {}


Please check formatting.

davidungar · 2018-05-16T21:45:46Z

docs/DriverParseableOutput.rst


 Example::

   {
     "kind": "began",
     "name": "compile",
     "pid": 12345,
+     "process": {
+       "real_pid": 12345


pid and real_pid have some potential to create confusion, but I don't see answer, and it's not your fault, anyway.

The main problem here is that 'pid' is re-used, but I also don't see another solution without breaking infrastructure that relies on this.

davidungar · 2018-05-16T21:49:16Z

include/swift/Driver/ParseableOutput.h

@@ -29,15 +29,19 @@ class Job;
 namespace parseable_output {

 /// \brief Emits a "began" message to the given stream.
-void emitBeganMessage(raw_ostream &os, const Job &Cmd, int64_t Pid);
+void emitBeganMessage(raw_ostream &os, const Job &Cmd, int64_t Pid,
+                      sys::TaskProcessInformation Process);


Echoing Graydon, Process is the wrong name here. I'd be fine with TPI (pi could be interpreted as 3.14) or processInfo.
Also it would be nice to be consistent (locally) on matters of casing. In other words, either OS instead of os, or cmd and pid and tpi. (Sigh, the casing is a nitpick, I know.)

I renamed it to ProcessInfo already, just want to fix the other concerns as well before pushing it :) Interpreting pi as the number pi is an interesting thought though :D It could also be interpreted as 🍰.
I didn't create the signature of the function but it seems to be convention in llvm to write variables in UpperCamelCase, os however refers better to output stream than OS which could indicate operating system. It's not ideal but I would like to keep it like that.

I think I've seen OS for output stream, and I keep thinking operating system, yes. Feel free to keep it as is.

davidungar · 2018-05-16T21:53:46Z

include/swift/Basic/TaskQueue.h

@@ -39,6 +41,57 @@ enum class TaskFinishedResponse {
  StopExecution,
 };

+/// TaskProcessInformation contains information about the process a task was
+/// associated with.
+struct TaskProcessInformation {


I'm still looking for more info concerning how this information will or might be used.

Also TaskProcessInformation is OK, if a bit awkward. "Information" could be anything, including the execution arguments. Is there a more specific term? Right now, its "times". Are you planning to generalize? Or would "TaskExecutionStatistics" cover it?

Now that this contains the real_pid I see it as a container for all 'information' about the OS process that ran. The times/usage are one part of it, real_pid is the other (for now). I don't plan to add more to this but it could contain other information like the user who started it (which is pretty useless in this case).

davidungar

Much better! I think the main thing I'm missing now is a comment explaining how the new info will be used (unless it's there & I missed it). Think about someone porting this code to a platform where there's a different facility than rusage that gives different info. What would he have to know about the info that is really needed and in what form? Or what would break if all the times were zero?

BenchR267 · 2018-05-18T15:48:55Z

@swift-ci please smoke test

BenchR267 · 2018-05-22T15:23:42Z

@graydon @davidungar could you please take another look? Thanks :)

davidungar

Had a good offline discussion. LGTM!

davidungar · 2018-05-18T04:04:01Z

include/swift/Basic/TaskQueue.h

+/// tasks ran in the same process (in multifile-mode or when WMO is activated
+/// e.g.). If available, it also contains information about the usage of
+/// resources like CPU time or memory the process used in the system. How ever,
+/// this could differ from platform to platform and is therefore optional.


Two thoughts:

(nitpick) If the comment says "task resource usage", why is the name not TaskResourceUsage?

The "If available" sentence is redundant and (redundantly) not specific enough. Why are you making this change? Is there some specific use you have in mind? For instance, "When available, an Xcode extension will provide a changing desktop color indicating how fast the compilations are running." In other words, I want to know what might break if I as a maintainer, mess this up in the future?

This is explicitly to not about task resource usage but about the usage of the process that ran this task. But it might be worth mentioning that this is the case. The difference between the two is already becoming very confusing!
A process can run multiple tasks (e.g. a process that compiles 5 swift files) but still all tasks are separately outputted. The usage relates always to the process so if someone would like to sum all usages up, (s)he should unique by real-pid first. I'll add this to the comment since it's very essential!
The 'if available' relates to the fact that this is depending on the rusage and wait4 symbols. If they are not available on your system, you also don't get any usage information. You could also run the driver by stating skip-execution and you would also get no usage information. I'll also add this to the comment!

Thanks for the talk, really appreciate your feedback! :)

Yes, it sure can be confusing.Your comment will be great! My pleasure, I enjoyed it.

BenchR267 · 2018-05-24T01:06:16Z

@swift-ci please smoke test

graydon

Looks ok to me, though would like to see the cpp chatter moved to 0th column.

graydon · 2018-05-25T18:29:27Z

lib/Basic/Unix/TaskQueue.inc

+#ifndef __APPLE__
+            // Apple systems report bytes; everything else appears to report KB.
+            this->ProcessUsage.getValue().Maxrss <<= 10;
+            #endif // __APPLE__


Bad indentation on the endif here.

graydon · 2018-05-25T18:31:07Z

lib/Basic/Unix/TaskQueue.inc

  for (;;) {
    int Status = 0;
+
+    #if defined(HAVE_GETRUSAGE) && !defined(__HAIKU__) && defined(HAVE_WAIT4)


Please put preprocessor directives in column 0.

When providing the -parseable-output flag to the swift compiler, it will provide json formatted messages about tasks that run. I added some optional usage information in form of user time, system time and maxrss to the output. This can be used by other tools using the compiler to get some insights about time and memory usage. Since the output does not longer match processes run (in batch mode), I also added a real_pid field so the client could reason about jobs that belong together if needed. rdar://39798231

BenchR267 · 2018-05-25T20:13:46Z

@swift-ci please smoke test

BenchR267 requested review from graydon and davidungar May 8, 2018 20:00

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 5 times, most recently from 7d23272 to 48f7340 Compare May 14, 2018 17:19

davidungar suggested changes May 15, 2018

View reviewed changes

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 6 times, most recently from 7112672 to 1ca1aac Compare May 15, 2018 21:46

jakepetroules reviewed May 15, 2018

View reviewed changes

docs/DriverParseableOutput.rst Outdated

"exit-status": 0

"exit-status": 0,

"process": {

"real_pid": 31232,

Copy link

Contributor

jakepetroules May 15, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here

jakepetroules reviewed May 15, 2018

View reviewed changes

docs/DriverParseableOutput.rst Outdated

"signal": 4

"signal": 4,

"process": {

"real_pid": 31232,

Copy link

Contributor

jakepetroules May 15, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

again

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 3 times, most recently from 13c285d to 18c4c14 Compare May 15, 2018 22:14

BenchR267 changed the title ~~[Driver] Added metrics to emitted messages~~ [Driver] Added process information to emitted task messages May 15, 2018

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 4 times, most recently from 579c9b1 to 5133e5a Compare May 16, 2018 15:47

graydon suggested changes May 16, 2018

View reviewed changes

davidungar reviewed May 16, 2018

View reviewed changes

davidungar suggested changes May 16, 2018

View reviewed changes

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 5 times, most recently from 2d71325 to 0f6ea7d Compare May 18, 2018 15:47

davidungar approved these changes May 22, 2018

View reviewed changes

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch 5 times, most recently from 285dc0f to e49d954 Compare May 24, 2018 01:03

graydon approved these changes May 25, 2018

View reviewed changes

BenchR267 force-pushed the feature/add-metrics-to-driver-output branch from e49d954 to ac10fb3 Compare May 25, 2018 20:13

BenchR267 merged commit 07d4303 into swiftlang:master May 25, 2018

BenchR267 deleted the feature/add-metrics-to-driver-output branch May 25, 2018 23:49

[Driver] Added process information to emitted task messages #16444

[Driver] Added process information to emitted task messages #16444

Uh oh!

Conversation

BenchR267 commented May 8, 2018

Uh oh!

BenchR267 commented May 14, 2018

Uh oh!

graydon commented May 14, 2018

Uh oh!

jrose-apple commented May 14, 2018

Uh oh!

BenchR267 commented May 14, 2018

Uh oh!

jrose-apple commented May 14, 2018

Uh oh!

BenchR267 commented May 14, 2018

Uh oh!

graydon commented May 15, 2018

Uh oh!

BenchR267 commented May 15, 2018

Uh oh!

graydon commented May 15, 2018

Uh oh!

davidungar left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BenchR267 May 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BenchR267 May 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BenchR267 commented May 15, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

BenchR267 May 15, 2018 •

edited

Loading

BenchR267 May 15, 2018 •

edited

Loading

BenchR267 May 17, 2018 •

edited

Loading