[JIT] Experimental logging/counters API #18235

jamesr66a · 2019-03-20T19:16:14Z

This defines a generic counters API that users can utilize to provide monitoring functionality in e.g. a production service. We expose both counters for runtime internals as well as a TorchScript API to create user-defined counters. Synopsis of the API:

torch/csrc/jit/script/logging.h specifies the externally-facing API in C++
torch/jit/_logging.py specifies the Python API

We use an interface, LoggerBase, to define the interactions between users and a logging backend. Implementing a subclass of LoggerBase allows the user to handle these events in a custom way, such as logging into a DB or calling into an infra-specific counters API.

From the frontend perspective, we can create log events in two ways:

We provide an add_stat_value(name, val) function. This calls into the Logger backend with a key/value pair. For example, we might call add_stat_value('foo', 1) to bump an event counter.
We provide a time_point() function to record a timestamp in nanoseconds. This can be used in conjunction with add_stat_value to record runtime wall clock durations.

Examples of frontend usage can be found in test_jit.py TestLogging.

We provide a trivial LockingLogger implementation as an example and for testing purposes. It is likely not ready for production usage. It demonstrates that a backend implementing the API can do things like specify aggregation types and report these aggregate stats via the get_counters() API.

facebook-github-bot

@jamesr66a has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

facebook-github-bot

@jamesr66a has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

suo · 2019-03-21T04:07:18Z

torch/csrc/jit/interpreter.cpp

          // std::cout << "pop reg[" << reg << "];\n" << registers[reg] << "\n";
        }
        pc = new_pc;
+        logging::getLogger()->addStatValue(


We should be very careful about logging in hot portions of the core runtime, since it adds a synchronization point between threads which can quickly become contended. It's not clear to me whether the counters we have here are valuable enough to justify that overhead—they seem too low level to tell us very much.

suo · 2019-03-21T04:08:41Z

torch/csrc/jit/script/logging.cpp

+      case AggregationType::SUM: {
+        float sum = 0;
+        for (auto x : kv.second)
+          sum += x;


braces here please, and at the other loops in this file

suo · 2019-03-21T04:13:02Z

torch/csrc/jit/register_prim_ops.cpp

+     // HACK alert: stuffing a struct into a ByteTensor
+     Operator("prim::TimePoint() -> Tensor", [](const Node* node) {
+      return [](Stack& stack) {
+        logging::JITTimePoint *ptr = new logging::JITTimePoint(logging::timePoint());


Can we add a comment to revisit this when c++-bound script classes are available

suo · 2019-03-21T06:09:00Z

torch/csrc/jit/script/logging.h

+TORCH_API void recordDurationSince(const std::string& name, JITTimePoint tp);
+
+namespace runtime_counters {
+constexpr const char* GRAPH_EXECUTORS_CONSTRUCTED =


Why not just use Symbol for these?

suo · 2019-03-21T06:15:51Z

torch/csrc/jit/script/logging.h

+ public:
+  TORCH_API virtual void addStatValue(
+      const std::string& stat_name,
+      float val) = 0;


lets use an int64_t instead of a float. Generally the stat values represent countable units, either events or milliseconds or whatever. I think it better matches fb303's interface as well.

suo · 2019-03-21T06:24:28Z

torch/csrc/jit/script/logging.cpp

+std::shared_ptr<LoggerBase> global_logger = std::make_shared<NoopLogger>();
+
+std::shared_ptr<LoggerBase> getLogger() {
+  std::unique_lock<std::mutex> lk(m);


This will definitely be a problem, since all logging to all keys will contend for this lock. Do we have a RW lock/shared mutex implementation that we can use here? If we don't have that, we'll have to come up with a better way to make this thread safe

suo · 2019-03-21T16:24:41Z

torch/csrc/jit/script/logging.h

+  TORCH_API virtual void addStatValue(
+      const std::string& stat_name,
+      float val) = 0;
+  TORCH_API virtual std::unordered_map<std::string, float> getCounters()


Maybe getCounterValue is a better interface, to avoid aggregating/copying the entire logger when we want to get a single counter

facebook-github-bot

@jamesr66a has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

addressed

zdevito

I am not opposed to having some logging. But at is size, it seems like too much code to support into the future given what it provides. I think it can be cut down quite a bit by using existing bindings and simplifying the aggregation code.

zdevito · 2019-03-22T19:13:28Z

torch/csrc/jit/register_prim_ops.cpp

+     }),
+     Operator("prim::BumpCounter(str key, int val) -> ()", [](const Node* node) {
+       return [](Stack& stack) {
+         auto val = pop(stack).toInt();


Nit: use in-order pop rather than stack manipulation code.

std::string key; int64_t val; pop(stack, key, value);

zdevito · 2019-03-22T19:14:11Z

torch/csrc/jit/register_prim_ops.cpp

+         return 0;
+       };
+     }),
+     Operator("prim::GetCounters(str name) -> int", [](const Node* node) {


nit: GetCounter

zdevito · 2019-03-22T19:26:57Z

torch/csrc/jit/script/init.cpp

  } else if (
      obj.ptr() == py::module::import("torch.jit").attr("annotate").ptr()) {
    return std::make_shared<AnnotateValue>();
+  } else if (


Please to not edit this core code with arbitrary primitive builtins. There is already a way to associate existing python functions with builtins _find_builtin below.

zdevito · 2019-03-22T19:29:28Z

torch/csrc/jit/register_prim_ops.cpp

       };
-     })});
+     }),
+     Operator("prim::BumpCounter(str key, int val) -> ()", [](const Node* node) {


Can you just use Peter's API for registering custom, tracable, operators? This would automatically generate all of the (1) implementation, (2) python binding, and (3) tracing code for you. It is what it was designed for. As it currently is, this PR reproduces that work.

zdevito · 2019-03-22T20:41:51Z

torch/csrc/jit/script/logging.cpp

+  return previous;
+}
+
+JITTimePoint timePoint() {


I'd just use inline int64_t getTime( which returns nanoseconds as an int64_t. This means we stick with the type system already available in TorchScript.

zdevito · 2019-03-22T20:47:44Z

torch/csrc/jit/script/logging.h

+
+ private:
+  mutable std::mutex m;
+  std::unordered_map<std::string, std::vector<int64_t>> raw_counters;


why not just:

struct Counter { int64_t sum; size_t count; }; std::unordered_map<std::string, Counter> raw_counters;

You get both sum an avg, and do not need to ever allocate memory.

zdevito · 2019-03-22T20:49:16Z

torch/csrc/jit/script/logging.cpp

+                                                : AggregationType::SUM;
+    vals = &raw_counters.at(name);
+  }
+  switch (type) {


race! You released the lock on the hash table. It has resized and then moved the contained vector to another address. *vals is invalid.

sidazhang · 2019-03-22T22:23:04Z

This looks amazing

We provide a time_point() function and a record_duration_since(name, time_point) API to record durations. These two functions can be used in conjunction to time certain sections of a model and log the wall time elapsed.

How does this play in cuda world, since cuda is asynchronous?

jamesr66a · 2019-03-25T20:44:56Z

@sidazhang I believe this would not accurately measure CUDA runtime for the reason you point out. I think i'll make a follow-up task to address that

zdevito

I think the implementation looks good. I have questions about naming consistency and what the API should be when retrieving a counter value.

zdevito · 2019-03-27T05:10:59Z

torch/csrc/jit/register_prim_ops.cpp

+          auto key = pop(stack).toString();
+
+          auto schema = parseSchema("prim::BumpCounter(str key, int val) -> ()");
+          if (jit::tracer::isTracing()) {


I don't like the fact that we have to manually write tracing code for these. This is because of a bug in the custom API that @smessmer has a PR with a fix out for. Can we make sure to update this when the fix lands?

Can you use torch::RegisterOperators instead of torch::jit::RegisterOperators? It doesn't give you a Stack but concrete types and you don't need to do tracing manually. Or is this a special case that wouldn't work with that?

zdevito · 2019-03-27T05:13:31Z

torch/csrc/jit/script/logging.cpp

+void recordDurationSince(const std::string& name, JITTimePoint tp) {
+  auto end = std::chrono::high_resolution_clock::now();
+  // Measurement in microseconds.
+  auto seconds = std::chrono::duration<double>(end - tp.point).count() * 1e6;


Why not nanoseconds? Otherwise granularity is at the microsecond level for no good reason.

zdevito · 2019-03-27T05:16:47Z

torch/csrc/jit/register_prim_ops.cpp

+          auto val = pop(stack).toInt();
+          auto key = pop(stack).toString();
+
+          auto schema = parseSchema("prim::BumpCounter(str key, int val) -> ()");


Why is this called prim::BumpCounter when the C++ function is called addStatValue? Can this be made consistent?

Because I didn't want to have to rebuild the world after changing interned_strings.h :p let me change it now

zdevito · 2019-03-27T05:19:38Z

torch/csrc/jit/script/logging.h

+  TORCH_API virtual void addStatValue(
+      const std::string& stat_name,
+      int64_t val) = 0;
+  TORCH_API virtual int64_t getCounterValue(const std::string& name) const = 0;


What is the expected contract here? At this level it is abstract what getCounterValue returns. In the example it is aggregated value, but the aggregation type is set per-stat by a subclass. It is weird that half the API is in the abstract class.

zdevito · 2019-03-28T23:35:39Z

aten/src/ATen/core/interned_strings.h

  _(prim, SetAttr)                 \
  _(prim, GetAttr)                 \
+  _(prim, AddStatValue)            \
+  _(prim, GetCounter)              \


This is dead

facebook-github-bot

@jamesr66a is landing this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

Summary: This defines a generic counters API that users can utilize to provide monitoring functionality in e.g. a production service. We expose both counters for runtime internals as well as a TorchScript API to create user-defined counters. Synopsis of the API: - `torch/csrc/jit/script/logging.h` specifies the externally-facing API in C++ - `torch/jit/_logging.py` specifies the Python API We use an interface, `LoggerBase`, to define the interactions between users and a logging backend. Implementing a subclass of `LoggerBase` allows the user to handle these events in a custom way, such as logging into a DB or calling into an infra-specific counters API. From the frontend perspective, we can create log events in two ways: 1. We provide an `add_stat_value(name, val)` function. This calls into the Logger backend with a key/value pair. For example, we might call `add_stat_value('foo', 1)` to bump an event counter. 2. We provide a `time_point()` function to record a timestamp in nanoseconds. This can be used in conjunction with `add_stat_value` to record runtime wall clock durations. Examples of frontend usage can be found in `test_jit.py TestLogging`. We provide a trivial `LockingLogger` implementation as an example and for testing purposes. It is likely not ready for production usage. It demonstrates that a backend implementing the API can do things like specify aggregation types and report these aggregate stats via the `get_counters()` API. Pull Request resolved: pytorch/pytorch#18235 Differential Revision: D14545060 Pulled By: jamesr66a fbshipit-source-id: 04099543a1898cfdd411511e46e03d5dce9b4881

facebook-github-bot · 2019-03-30T01:05:15Z

@jamesr66a merged this pull request in 85f3601.

Summary: Resubmit #20698 which got messed up. Idea is that when PyTorch is used in a custom build environment (e.g. Facebook), it's useful to track usage of various APIs centrally. This PR introduces a simple very lightweight mechanism to do so - only first invocation of a trigger point would be logged. This is significantly more lightweight than #18235 and thus we can allow to put logging in e.g. TensorImpl. Also adds an initial list of trigger points. Trigger points are added in such a way that no static initialization triggers them, i.e. just linking with libtorch.so will not cause any logging. Further suggestions of what to log are welcomed. Pull Request resolved: #20745 Differential Revision: D15429196 Pulled By: dzhulgakov fbshipit-source-id: a5e41a709a65b7ebccc6b95f93854e583cf20aca

apaszke

Is this actually used by anyone? It seems that we're starting to get a lot of requests for logging in the library and maybe we should start a more principled approach instead of developing 3 different interfaces

apaszke · 2019-07-02T10:49:15Z

torch/csrc/jit/script/logging.cpp

+    previous = global_logger.load();
+  }
+  return previous;
+}


This leaks the previous logger

apaszke · 2019-07-02T10:49:46Z

torch/csrc/jit/script/logging.cpp

+}
+
+JITTimePoint timePoint() {
+  return JITTimePoint{std::chrono::high_resolution_clock::now()};


std::chrono is extremely slow on many platforms. We have better timing code in the autograd benchmark.

apaszke · 2019-07-02T10:50:21Z

torch/csrc/jit/script/logging.h

+ public:
+  TORCH_API virtual void addStatValue(
+      const std::string& stat_name,
+      int64_t val) = 0;


Why don't we make this into a generic API that takes an IValue instead?

James Reed added 11 commits March 19, 2019 10:52

Counter logging

c7c33cd

Add some logging statements in execution machinery

d10582c

update API

00af989

start tracing

28a7016

trace stat bump

c867ee5

time measurement

345995e

time measurement from script

325aba3

Change set logger api

160339d

Aggregation API

b0f3619

factor runtime counters & make API to query them

f8ca49e

Minor cleanup

0845bf8

jamesr66a requested review from suo and zdevito March 20, 2019 19:16

facebook-github-bot added the oncall: jit Add this issue/PR to JIT oncall triage queue label Mar 20, 2019

facebook-github-bot reviewed Mar 20, 2019

View reviewed changes

James Reed added 3 commits March 20, 2019 14:20

windows build, clang-tidy and lint fixes

cb5662c

more fixes

f78e365

clang-format

7f08cfa

facebook-github-bot reviewed Mar 20, 2019

View reviewed changes

suo previously requested changes Mar 21, 2019

View reviewed changes

James Reed added 3 commits March 21, 2019 14:23

address commits

fea8a18

address more comments

5f38535

add atomic include

20e2aae

facebook-github-bot reviewed Mar 21, 2019

View reviewed changes

jamesr66a requested a review from suo March 22, 2019 17:29

zdevito reviewed Mar 22, 2019

View reviewed changes

address zdevito comments

8e9a2f1

jamesr66a force-pushed the counters branch from 60f19f1 to 8e9a2f1 Compare March 23, 2019 01:23

Use raw counter struct

31e1fea

jamesr66a requested a review from zdevito March 25, 2019 19:52

zdevito reviewed Mar 27, 2019

View reviewed changes

address comments

1a82453

jamesr66a force-pushed the counters branch from 3630be6 to 1a82453 Compare March 27, 2019 20:01

zdevito approved these changes Mar 28, 2019

View reviewed changes

remove prim::GetCounter

62ff971

facebook-github-bot reviewed Mar 29, 2019

View reviewed changes

facebook-github-bot closed this in 85f3601 Mar 30, 2019

facebook-github-bot added the merged label Mar 30, 2019

This was referenced May 20, 2019

Lightweight at-most-once logging for API usage #20698

Merged

Lightweight at-most-once logging for API usage #20745

Closed

apaszke reviewed Jul 2, 2019

View reviewed changes

[JIT] Experimental logging/counters API #18235

[JIT] Experimental logging/counters API #18235

Uh oh!

Conversation

jamesr66a commented Mar 20, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

facebook-github-bot left a comment

Choose a reason for hiding this comment

Uh oh!

facebook-github-bot 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!

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!

facebook-github-bot left a comment

Choose a reason for hiding this comment

Uh oh!

zdevito 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!

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!

sidazhang commented Mar 22, 2019

Uh oh!

jamesr66a commented Mar 25, 2019

Uh oh!

zdevito left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

smessmer Jul 2, 2019 • 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!

facebook-github-bot left a comment

Choose a reason for hiding this comment

Uh oh!

facebook-github-bot commented Mar 30, 2019

Uh oh!

apaszke left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jamesr66a commented Mar 20, 2019 •

edited

Loading

smessmer Jul 2, 2019 •

edited

Loading