Tracing Dataset Events

[jackye1995]

Thanks to @yanghua for adding the tracing events for dataset in #4057. There are some lingering topics regarding tracing I would like to discuss here.

cc @westonpace @wjones127 @Xuanwo

[jackye1995]

1. we have an event for tracing dataset open. I am a bit worried if this would create a lot of noisy events. Should we separate them into different targets? Does that affect performance? I am not personally familiar with the perf implication of tracing and would like to know what others think.

[westonpace]

I think as long as the events are per-query / per-request then the performance is probably fine. Event processors typically just throw the events into a queue and have another thread that processes the events so the actual recording of the event is very lightweight. Then, if too many events arrive at once, the queue overflows and some events will get dropped on the floor.

I think per-batch or per-row events would be too noisy.

[westonpace]

Generally I'm in favor of more logging / tracing and then dialing it back when things get too noisy or we decide a signal isn't that useful. Maybe we should formally list which events are supported somewhere. These events won't change without at least some discussion.

Then we can have experimental events which aren't in the formal event list but we are testing out. If we've had them in practice for a while, found them to be useful, and haven't had performance trouble with them, then we can mark the events supported.

[yanghua]

Maybe we should formally list which events are supported somewhere.

+1 for this point

IMO, from some point of view, the events are like APIs; if we support, we should provide compatibility of the event and args. Because there may be consumers are consume them.

[jackye1995]

+10000 on formally listing the events

[jackye1995]

2. I think we should also trace the events happening in scanner, this is pretty important info for optimization. What do we think?

[yanghua]

Interesting idea, for scanner, IMO, it's a choice about when we use tracing or when we use log. Is it enough to only add some logs for analysis? The main purpose we want to have tracing is that we want to receive some events actively from a tracing subscriber. So that we can report to a remote service and track the lifecycle of a dataset, for instance, when a dataset triggers a opening event, so that we can invoke an LRU strategy. If we also want to collect events that come from the scanner. It would be better to have them.

[westonpace]

We should be emitting an event after a plan runs to completion where we log summary statistics (how long the scan took, how much I/O, etc.)

The other thing that is useful is logging the queries / plans themselves. However, this is more complicated. Queries can possibly contain sensitive information (e.g. maybe the filter is "password = {password}"). Also, queries can be pretty verbose and so it can be a lot of information. I think any event reporting the query itself should be opt-in. We could maybe also make it so that only queries that take more than X seconds are sent as events (e.g. slow query logged).

it's a choice about when we use tracing or when we use log

Yes, I think there is a lot of overlap between tracing and logging. Tracing is structured and contains more formal context. Otherwise it is really just another layer of logging.

[jackye1995]

The main purpose we want to have tracing is that we want to receive some events actively from a tracing subscriber. So that we can report to a remote service and track the lifecycle of a dataset, for instance, when a dataset triggers a opening event, so that we can invoke an LRU strategy.

yeah I think typically the remote service can manage things like auto-compaction based on write events, but eventually it will need to extend to proactively organize data into an ideal layout based on user read pattern, that's why a subscribable event for query would be more useful than pure logging in my mind. I believe this is actually how commercial products like Databricks market their "AI optimizer for lakehouse"

[majin1102]

+1

[jackye1995]

3. currently we have the commit events representing data actually committed. We also have the XXXing events that represents an intent to perform certain operation, and that might succeed or fail in the end. Again, should they be separated targets?

[westonpace]

We have file audit events which report when a file is created / deleted. These are important I think to help answer the question of "what happened to this file"?

We also have open/load events that we more intended to report when the cache was not hit (e.g. we didn't hit index cache and so we must load the index from disk) to help explain slow queries (the latency is higher on this query because it had to load the index from disk)

[yanghua]

In production, we may have multiple versions of the SDK (write or read, maybe not one). So what about adding an event arg named, for example, client_version or sdk_version? @jackye1995

[yanghua]

And we may unify all the uri or path to return an absolute URI for a dataset. WDYT?

[jackye1995]

that sounds reasonable to me