track each subquery field proc separately

[kindermax]

This fix aims to improve subquery fields tracking.

Problem

Let's consider case when several fields are resolved using same subgraph. In this case both fields will have the same duration (from superSlowField), but this is wrong.

Field('id', Integer, user_sg.c(get_user_id(S.this.id))),
Field('superSlowField', Integer, user_sg.c(get_super_slow_field(S.this.id))),

In production it looks like this:

Solution

We need to track each field resolver individually. In this pr wrap_proc will wrap field's proc function (proc function is basically a function with @define decorator on it) so instead of tracking result = result_proc() which is a _create_result_proc we will track each proc individually, see:

hiku/hiku/sources/graph.py

Lines 50 to 58 in 8b5598c

	def _create_result_proc(
	engine_query: Query, procs: List[Callable], options: List
	) -> Callable[[], List[List]]:
	def result_proc() -> List[List]:
	sq_result = engine_query.result()
	return [[proc(this, sq_result, *opt_args)
	for proc, opt_args in zip(procs, options)]
	for this in sq_result[THIS]]
	return result_proc

Result

Simple example which prints observe args

Before:

--- OBSERVE Product id 0.6453857090018573
--- OBSERVE Product residueStatus 0.6453857090018573
--- OBSERVE Product residueColorStatus 0.6453857090018573
--- OBSERVE Product price 0.6453857090018573
--- OBSERVE Product currencyText 0.6453857090018573
--- OBSERVE Product _wholesale_prices 0.6453857090018573
--- OBSERVE Product wholesalePrices 3.5832999856211245e-05

After:

--- OBSERVE Product id 1.0446036259963876
--- OBSERVE Product residueStatus 1.0446859590010718
--- OBSERVE Product residueColorStatus 1.0447400010016281
--- OBSERVE Product price 1.0447855009988416
--- OBSERVE Product currencyText 1.0451795420012786
--- OBSERVE Product _wholesale_prices 1.1229197930006194
--- OBSERVE Product wholesalePrices 3.524999920045957e-05

[kindermax]

passing start_time from above allows to track subgraph execution + proc execution time.

[kindermax]

maybe it makes sense to place start_time = time.perf_counter() inside _proc_wrapper but then we are (probably) loosing subgraph(low-level graph) data exection time