Redundancy/Repeated calls in query function

[logan-keede]

Describe the bug

I was trying to make some changes to a function in datafusion-functions crate specifically in to_timestamp_impl function when I noticed that it is being called 7 times for query SELECT to_timestamp('2020-09-08 12/00/00+00:00');

This does not seem expected and it is probably causing efficiency drops and problems while troubleshooting bugs in functions.

This only seems to happen for function calls that are going to generate error anyways.

so far this has been replicated in to_timestamp and to_char but it can be probably be replicated in other functions too.

To Reproduce

edit invoke_batch function in implementation of ScalarUDFImpl trait for struct ToTimestampFunc to include a logging statement like

fn invoke_batch(
        &self,
        args: &[ColumnarValue],
        _number_rows: usize,
    ) -> Result<ColumnarValue> {
        println!("to_timestamp_impl is being called");

then in datafusion-cli

> select to_timestamp('1');
to_timestamp_impl is being called
to_timestamp_impl is being called
to_timestamp_impl is being called
to_timestamp_impl is being called
to_timestamp_impl is being called
to_timestamp_impl is being called
to_timestamp_impl is being called
Arrow error: Parser error: Error parsing timestamp from '1': timestamp must contain at least 10 characters


> select to_timestamp('2023-01-31T09:26:56-05:00', '%+');
to_timestamp_impl is being called
+------------------------------------------------------------+
| to_timestamp(Utf8("2023-01-31T09:26:56-05:00"),Utf8("%+")) |
+------------------------------------------------------------+
| 2023-01-31T14:26:56                                        |
+------------------------------------------------------------+
1 row(s) fetched. 
Elapsed 0.005 seconds.

> select to_char('1'::time, '%Y-%m-%d');
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
to_char is being called
Execution error: Cast error: Format error

Expected behavior

> select to_timestamp('1', '%d');
to_timestamp_impl is being called
Arrow error: Parser error: Error parsing timestamp from '1': timestamp must contain at least 10 characters

> select to_char('1'::time, '%Y-%m-%d');
to_char is being called
Execution error: Cast error: Format error

Additional context

No response

[alamb]

I think the next step to debug this would be to run this test under a debugger or print out the stack somehow to see from where this function is being called

[alamb]

I think figuring out where the code is being called is a great first issue. Depending on the answer to that this might be "working as expected" or a bug to fix further

[TheBitsmith]

Take

[alamb]

Thanks @TheBitsmith -- it would be great if you could post any information you are able to find out to this ticket (like what the stack traces are)

[LukMRVC]

Hello, so I took a look at it.
In the to_timestamp case it seems, the UDFScalar invoke_with_args is called from a ConstEvaluator when an ExprSimplifier is trying to rewrite the expression. As it's trying simplify within simplify_with_cycle_count the ConstEvaluator returns the original expression wrapped in Transformed::yes even on SimplyRuntimeError, it breaks on when reaching max_cycles which is 3 by default. I guess. This happens 2 times, I guess first when traversing down and then back up while trying to optimize the plan, not sure about this. Finally, when executed it is invoked one last time.

For the to_char, the reason for multiple invocations seems to be the same, returning the original expression wrapped with Transformed::yes when evaluating.

[LukMRVC]

Take

[LukMRVC]

So, I'm not sure about the next steps towards resolving this issue. It seems, that this is actually a case of "working as expected", however I recognize that it may be a bit counter intuitive at first. Maybe some documentation could be enough?

[jayzhan211]

working as expected

I notice this before, I think this is something to be optimized "if possible" and not expected.
This is probably not a good first issue but the optimization issue

[jayzhan211]

I check simplify_with_cycle_count with the query select to_timestamp('1')

datafusion/datafusion/optimizer/src/simplify_expressions/expr_simplifier.rs

Lines 193 to 223 in fc2fbb3

	pub fn simplify_with_cycle_count(&self, mut expr: Expr) -> Result<(Expr, u32)> {
	let mut simplifier = Simplifier::new(&self.info);
	let mut const_evaluator = ConstEvaluator::try_new(self.info.execution_props())?;
	let mut shorten_in_list_simplifier = ShortenInListSimplifier::new();
	let mut guarantee_rewriter = GuaranteeRewriter::new(&self.guarantees);
	if self.canonicalize {
	expr = expr.rewrite(&mut Canonicalizer::new()).data()?
	}
	// Evaluating constants can enable new simplifications and
	// simplifications can enable new constant evaluation
	// see `Self::with_max_cycles`
	let mut num_cycles = 0;
	loop {
	let Transformed {
	data, transformed, ..
	} = expr
	.rewrite(&mut const_evaluator)?
	.transform_data(|expr| expr.rewrite(&mut simplifier))?
	.transform_data(|expr| expr.rewrite(&mut guarantee_rewriter))?;
	expr = data;
	num_cycles += 1;
	if !transformed || num_cycles >= self.max_simplifier_cycles {
	break;
	}
	}
	// shorten inlist should be started after other inlist rules are applied
	expr = expr.rewrite(&mut shorten_in_list_simplifier).data()?;
	Ok((expr, num_cycles))
	}

I think the TransformedResult might not be correct when we apply the rewrite, the Expr is unchanged but transformed is true. If we correctly return Transformed::no we can leave the loop earlier

expr: to_timestamp(Utf8("1"))
invoke_with_args timestamp is called
transformed_expr: to_timestamp(Utf8("1"))
transformed: true
expr: to_timestamp(Utf8("1"))
invoke_with_args timestamp is called
transformed_expr: to_timestamp(Utf8("1"))
transformed: true
expr: to_timestamp(Utf8("1"))
invoke_with_args timestamp is called
transformed_expr: to_timestamp(Utf8("1"))
transformed: true
expr: to_timestamp(Utf8("1"))
invoke_with_args timestamp is called
transformed_expr: to_timestamp(Utf8("1"))
transformed: true
expr: to_timestamp(Utf8("1"))
invoke_with_args timestamp is called
transformed_expr: to_timestamp(Utf8("1"))
transformed: true

[LukMRVC]

Yes, that's what happening as I mentioned in my previous comment.

When ConstEvaluator is trying to simplify into a scalar, the match expression is matched on ConstSimplifyResult::SimplifyRuntimeError making it return Transformed::yes variant.

datafusion/datafusion/optimizer/src/simplify_expressions/expr_simplifier.rs

Lines 521 to 541 in fc2fbb3

	fn f_up(&mut self, expr: Expr) -> Result<Transformed<Expr>> {
	match self.can_evaluate.pop() {
	// Certain expressions such as `CASE` and `COALESCE` are short-circuiting
	// and may not evaluate all their sub expressions. Thus, if
	// any error is countered during simplification, return the original
	// so that normal evaluation can occur
	Some(true) => match self.evaluate_to_scalar(expr) {
	ConstSimplifyResult::Simplified(s) => {
	Ok(Transformed::yes(Expr::Literal(s)))
	}
	ConstSimplifyResult::NotSimplified(s) => {
	Ok(Transformed::no(Expr::Literal(s)))
	}
	ConstSimplifyResult::SimplifyRuntimeError(_, expr) => {
	Ok(Transformed::yes(expr))
	}
	},
	Some(false) => Ok(Transformed::no(expr)),
	_ => internal_err!("Failed to pop can_evaluate"),
	}
	}

The comment there explains why for some expressions this is necessary. Maybe this can be improved for actually erroneous cases so that the loop within simplify_with_cycle_count can be exited earlier.