Revamping Loggers

[wmalpica]

The following is a summary of all the logs we have, what they log and what are their deficiencies:

input_comms/output_comms

• This logs all inbound and outgoing messages.
• Its generates a lot of logs which are useful for debugging communication issues. The issue of there being too many logs here is not a big problem, since we can now turn them off by default.

queries_logger

• This logs the following: ral_id|query_id|start_time|plan|query
• The plan is displayed as a JSON text where Relational algebra steps can have "children". This makes it easier to consume programatically, but not visually
• A big problem with this logger is that the plan it logs is the logical plan, not the physical plan

kernels_logger

• This logs the following: ral_id|query_id|kernel_id|is_kernel|kernel_type
• The kernels logged are both compute kernels and cacheMachines.
• This log is not meant to be consumed alone
• It logs in the CacheMachine constructors and kernel constructor

kernels_edges_logger

• This logs the following: ral_id|query_id|source|sink
• Which describes the relationship between the elements in kernels_logger
• Its only used in graph::add_edge

events_logger

• This logs the following: ral_id|query_id|kernel_id|input_num_rows|input_num_bytes|output_num_rows|output_num_bytes|event_type|timestamp_begin|timestamp_end
• The biggest problem with this logger is that its only used in a few of the kernel ::do_process functions. If we want to use this, it needs to be universally in all ::do_process functions.

cache_events_logger

• This logs the following: ral_id|query_id|source|sink|num_rows|num_bytes|event_type|timestamp_begin|timestamp_end
• Its used in:
  • BatchSequence::next() (and other similar next() functions)
  • OutputKernel::run()
  • kernel::add_to_output_cache
• The problem with this is that we no longer really use the ::next() functions.
• For this logger to work, we would need to properly log absolutely all CacheData movement on and off caches. Perhaps except the communication caches, since we have specific communication logs.

batch_logger

• This logs all sorts of events. Its structure is meant to be flexible, but that also makes it non-homogeneous, making harder to digest.
• This logger lots some things that likely should be logged in separate logs (and sometimes already is)
• The info in this logger is made to be relatively easy to consume on its own
• The following are examples of some things that it logs that is a little redundant with other logs:
  • Queries and their relational algebra. This is redundant with queries_logger
  • Cache_events: when things are added and removed from caches.
• The following are some things that are not captures anywhere and are useful:
  • Config options set
  • When a query starts and ends
  • Metadata gathered to determine partitioning strategies for order by or joins and what partitioning strategy was done
  • When a kernel is finished creating tasks
  • When a kernel is done done

Information we would like to be able to know

• How much time is spent in different steps of the graph?
• How much time is spent doing IO?
• How much time is spent communicating?
• How much time is spent caching and de-caching?
• Would like to be able to do analysis on the efficiency of caching and de-caching. For example, if we cached something to CPU, did it immediately get de-cached?

PROPOSED ACTIONS

• removing cache events type things from from batch_logger
• Improve queries_logger so that it has the physical plan and not the logical one
• Get rid of events_logger (replaced with task logger)
• Improve cache_events_logger by making sure all caching events are logged (adding to cacheMachines) and when we downgrading data (MemoryMonitor). I dont think we need to log when we pull out of cacheMachines.
• Introduce a new task_logger

task_logger Task logger would log tasks executed by the executor. It should only need to be in task::run(...):

• time started
• duration of de-caching
• duration of execution
• kernel_id
• input_num_rows
• input_num_bytes
• output_num_rows (lets add this at a later time)

• output_num_bytes (lets add this at a later time)

  (lets add this at a later time) We would make it so that all do_process would return rows and bytes output, so that we can log it.

In this alternate proposal, then we would be able to analyze time spent in all processing, caching (via cache_events_logger) and decaching (via task_logger). In this proposal, we would not be able to explicitly track every batch how it goes in and out and to where it come from and goes to. That is information that could be useful in a very very detailed debugging analysis. We have right now a little more of that info, but not by a lot.

[aucahuasi]

https://github.com/BlazingDB/blazingsql/issues/1305

[aucahuasi]

https://github.com/BlazingDB/blazingsql/issues/1306

[wmalpica]

Regarding:

Improve cache_events_logger by making sure all caching events are logged (adding to cacheMachines) and when we downgrading data (MemoryMonitor). I dont think we need to log when we pull out of cacheMachines.

Downgrading data is currently captured by batch_logger in CacheMachine.cpp in the function downgradeCacheData. We dont want batch_logger to capture that anymore. We want cache_events_logger to capture that somehow.