Fixing ExecuTorch Logging

[GregoryComer]

Logging for ExecuTorch is a critical part of debugability. Unfortunately, most users do not get ET logs. While we have the tools to expose it, it often doesn’t work or is difficult to use. In my experience, this is the single-largest driver of user frustration. We need to address this prior to ET 1.0.

Note: ExecuTorch does contain any telemetry. The discussion regarding production logging integration and routing are to give users hooks to route logs as desired.

Pain Points

• PAL overrides (including the ones for Android and iOS extensions) depend on weak symbol overrides, which are link order and type dependent. This makes it work unreliably in non-obvious ways (see below).
  • Buck does not provide a way to control link order.
  • Meta-internal builds may force dynamic linking in some contexts, which also breaks PAL overrides in non-obvious ways. As a result, there is no reliable way to do PAL overrides with buck - it sometimes works, sometimes not. CMake is better due to exposing more control over the build but is still fragile.
  • This causes logging to not work in Meta apps and pybindings with no way to fix it on the user side.
• PAL overrides can only be done from C/C++. When using the Java or Swift bindings, there is no easy way to do a PAL override.
  • We have Android and iOS-specific ways to get logs, but (a) they sometimes don’t work due to the above linkage issues, and (b) are fragmented between platforms.
• PAL overrides don’t scale well when multiple teams are sharing a runtime instance.

Regarding link order, if there is a weak symbol and strong symbol, the linker may not always take the strong symbol, it can take whichever it sees first (source). This means that if a user overrides the PAL log emit method, the user implementation may or may not be used, depending on the order that libraries are passed to the linker. In CMake, this can be controlled, but buck does not expose a control for this.

For example, if we have executorch.o with the framework and user.o with the override:
ld ... executorch.o user.o will not work, but ld ... user.o executorch.o will work. This is often hidden by the build system and not very obvious.

The other linkage issue is that the override has to be statically linked with the PAL itself. Within Meta-internal buck, we can't always control this. CMake gives more control, but there are cases where it may be desirable to have the log routing code live in a different .so.

Suggested Remediations

• Move the Android and iOS log routing into the default PAL. Logs will always work out of the box without needing extra targets.
  • Add Android and iOS PAL implementations (Hansong's suggestion), similar to the existing Posix implementation here: posix.cpp.
  • Alternatively we could conditionally compile in the correct log routing implementation in posix.cpp, but (a) is likely cleaner.
  • We probably want some type of build-time override to disable this behavior as some rarer cases want logs sent to stderr/stdout.
• Add a first-class log sink API to the core runtime.
  • Allow callers to subscribe to the log stream (via a user-provided callback) to get logs without overriding the PAL. Users empirically do not want to override the PAL.
  • Expose through Android + iOS bindings. iOS already has this, but using the “core” version under the hood will solve linkage issues. We also want a consistent API surface across languages and platforms to the extent possible.

// Maybe something like...
void register_log_subscriber(log_callback_t callback);
Error remove_log_subscriber(log_callback_t callback);

• Update the PAL override mechanism to use an in-memory function table rather than weak symbol overrides. This will solve linkage problems.
  • We can maintain backwards compatibility with the existing behavior by initializing the function pointers based on the current weak symbol mechanism.
  • To override, users can call an API and pass in a function pointer to their implementation.

// Maybe something like...
struct et_pal_table {
  et_pal_emit_log_message_t emit_log_message;
  // ...
};
et_pal_table* get_pal_table();

[JacobSzwejbka]

@dbort Do you have any thoughts on this?

[kirklandsign]

+1 Move the Android and iOS log routing into the default PAL

Android for sure.

[jackzhxng]

PAL overrides don’t scale well when multiple teams are sharing a runtime instance.

Just curious why is this case?

[GregoryComer]

Specifically, if there are multiple teams independently deploying models within a single app and they all want to redirect logs, only one can override. So they have to invent their own shared log routing mechanism for each case. Ideally we would have a way for multiple subscribers to get logs without them needing to coordinate and build a solution in each app.

[swolchok]

typedef struct

nit: don't use typedef struct in C++

[kirklandsign]

For other edge devices other than Android/iOS, I'm not sure what's the use case of a multi-subscriber pattern. Say for a specific board, they can override this with their own source (they need some config anyway) and they can dupe the output buffer themselves. We don't want to be too complicated within ET

[GregoryComer]

I'm fine to solve it only for mobile, so long as we fix the ore linking problems. But I do want to make sure that we can provide a C++ API on mobile to get logs that works on both Android + iOS so that they can write cross-platform code. If needed, we could add a build-time config to gate it out, but I'm not sure it's needed as hopefully it can be made very lightweight.

[kirklandsign]

For android, adding a check #ifdef __ANDROID__ and write to __android_log_print and otherwise use normal flow in

executorch/runtime/platform/default/posix.cpp

Lines 148 to 187 in 59dce3d

	void et_pal_emit_log_message(
	et_timestamp_t timestamp,
	et_pal_log_level_t level,
	const char* filename,
	ET_UNUSED const char* function,
	size_t line,
	const char* message,
	ET_UNUSED size_t length) {
	_ASSERT_PAL_INITIALIZED();
	// Not all platforms have ticks == nanoseconds, but this one does.
	timestamp /= 1000; // To microseconds
	unsigned long int us = timestamp % 1000000;
	timestamp /= 1000000; // To seconds
	unsigned int sec = timestamp % 60;
	timestamp /= 60; // To minutes
	unsigned int min = timestamp % 60;
	timestamp /= 60; // To hours
	unsigned int hour = timestamp;
	// Use a format similar to glog and folly::logging, except:
	// - Print time since et_pal_init since we don't have wall time
	// - Don't include the thread ID, to avoid adding a threading dependency
	// - Add the string "executorch:" to make the logs more searchable
	//
	// Clients who want to change the format or add other fields can override this
	// weak implementation of et_pal_emit_log_message.
	fprintf(
	ET_LOG_OUTPUT_FILE,
	"%c %02u:%02u:%02u.%06lu executorch:%s:%zu] %s\n",
	level,
	hour,
	min,
	sec,
	us,
	filename,
	line,
	message);
	fflush(ET_LOG_OUTPUT_FILE);
	}

[GregoryComer]

Yeah, I think that's a good solution for making sure we get logs out of box when running locally. The tricky thing is many teams don't have access to the logcat data in production and want to integrate with their own logging solution. They have no easy way to get logcat entries if inference is failing in production.

Within the wider open-source community, I could see similar use cases for integrating with other error reporting systems that users want to integrate in their application.

[kirklandsign]

Ah just realized this issue. So you think we should provide this subscriber, instead of user modify the source?

[larryliu0820]

I think the point of PAL is not being able to support multiple logging pipelines though. PAL is to abstract out the different running environment, not supporting multiple running environments as I don't believe that's a concrete requirement.

In other words, what is the problem we are solving here? I think in the end 1 application with ExecuTorch should only have to hook up with 1 primitive logging capability (concretely 1 et_pal_emit_log_message implementation). Like if you are building an android app, you only need an android implementation of et_pal_emit_log_message and same for pybind, I don't imagine any case you would want both.

If weak symbol doesn't satisfy the needs of plugin the correct implementation based on the target hardware, we should solve that issue. Having a subscriber pattern doesn't actually solve it, because it implies that we will have multiple listeners which I doubt is the case.

[GregoryComer]

Yeah, having the subscriber pattern is independent of the linkage fixes. It's more that it's a common request as people don't want to override the PAL to get logs, or can't, because they're writing Java code. Logcat is a good default for local, but is not sufficient for Meta-internal use. I've had multiple requests for this and Anthony has independently added it to the iOS bindings, so I think there's a strong case to implement it in a cross-platform manner rather than re-inventing it in a bunch of places.

[GregoryComer]

The other benefit of a subscriber API is that it allows for easily getting logs at runtime (from code). So that they can throw exceptions with more detail, for example, or otherwise log to their own mechanism in prod. Logcat lets you get the logs with a local device, but not from code. Ofc they can override the PAL, but I don't think it's user friendly for mobile.