Tuesday, June 01, 2010

Adding profiling and query plans to mondrian

I've long wanted to add query plans and profiling to mondrian's execution engine.

I just logged jira case MONDRIAN-754 with my ideas for how it would work, and I thought it would be good to share it as a blog post so I can gather opinions. Most of the rest of this post is taken straight from the jira case. Note that we are not committing to implement this feature in any particular release. It's just an idea we are kicking around.

Mondrian currently does not help you find out where the time is spent in executing a query, except for time spent in SQL. While most Mondrian queries are SQL-heavy, it would help to see the breakdown.

Specifically: (a) it would increase understanding of the engine by showing the physical plan (Calc nodes) that mondrian has chosen (including caching of results, choice of iterator versus list representation of sets), (b) it would help identify problems where a particular leaf expression that generates SQL is executed repeatedly and generates very similar SQL statements (see e.g. MONDRIAN-723); and (c) it would help developers identify MDX functions taking longer than expected, or sub-optimal plans, and thereby tune mondrian.

I propose to add a profiling mode with two levels.

At the lower level, mondrian would print the plan of each MDX query as it executed it:

Select(cube="[Cube]" mdx="with set [Foo xxx] AS [Foo].Children select non empty [Foo xxx] on 0, [Bar] * [Baz] on 1 from [Cube] where [Gender].[M]")
= CalculatedSets
=== CalculatedSet(name="Foo xxx", format="iterable")
===== Children(format="list")
======= HierarchyExpr(uniqueName="[Foo]")
= FilterAxis
=== MemberExpr(uniqueName="[Gender].[M]")
= Axes
=== Axis(ordinal="0", nonEmpty="true")
===== SetExpr(name="[Foo xxx]", format="iterable")
=== Axis(ordinal="1", nonEmpty="false")
===== CrossJoin
======= Call(function="{}")
========= Call(function="CURRENTMEMBER")
=========== HierarchyExpr(uniqueName="[Bar]")
======= Call(function="{}")
========= Call(function="CURRENTMEMBER")
=========== HierarchyExpr(uniqueName="[Baz]")

Format. I've used leading '=' to preserve indentation in this bug report. I would use spaces in this bug report. I'd use spaces in the actual feature. Or we could use XML.

There isn't much difference between the physical plan and the MDX query because this is a simple example. Note that '[Foo]' has been expanded as if the user had written '{[Foo].CurrentMember}'. Differences in more complex plans include: constant reduction; introduction of Cache operator; choice of physical format (list, mutable list, iterator); adapters to change physical format (e.g. copy a list to make it mutable); pushdown of non-empty and other constraints to native SQL; strategies for evaluating named sets (first time, each time).

Optionally each node could contain extra static information: the type (e.g. Integer, String, Numeric, Member(hierarchy='Store'), Set(Tuple(Member(hierarchy=[Store]), Member(level=[Time].[Year])))); format (list, mutable list, iterator); list of hierarchies an expression is dependent on (important for cached expressions).

With the higher level of profiling, mondrian would gather information while the plan is running. The number of times a node is executed, and amount of time in that node and its children. From that we can also compute the amount of time in the node alone. At the end of execution, mondrian would print the plan tree again, with "count", "self" and "self+children" values attached to each node.

Of course there is always an overhead to collecting profiling info. We would not recommend that people run production applications with profiling enabled. The question is always whether the numbers gathered from the profiled system are representative of the system running in its normal mode. Call count would be 100% accurate, and elapsed time should be within a few microseconds per call, so the profiling would serve its purpose.

10 comments:

Daniel Lemire said...

Excellent!

Anyhow, you only want profiling info for problematic queries, so who cares about a microsecond?

Julian Hyde said...

Daniel,

Glad you like the idea.

I worry a little that people will forget to compensate for the profiling overhead. Suppose a leaf-level calculation, such as multiplying two cell values, is executed millions of times. With profiling overhead, it might appear to be 25% of the plan total, and people would complain that our multiply operation is too slow; but in fact it's only really 5% of the total.

The only real solution is to educate people how interpret the results of a profiler.

I am tempted to make this mistake every time I profile Java or C++ code. I have to remind myself that calls which are faster than say 10 microseconds per call are mostly profiling overhead, and I just need to ignore them.

Julian

Anonymous said...

What about making this more part of Schema Designer, or an option on the Mondrian call, so that production doesn't get slowed down, but design / implementation can see the information to tweak / clean their designs?

Julian Hyde said...

Anonymous,

We could certainly surface the 'query plan' part of the feature in the Workbench. But the 'profiling' feature is only meaningful when applied to actual queries with significant amounts of data.

Pedro Alves said...

What about a EXPLAIN that generates that log?

It's not standard mondrian, but the same for sql and most db's implement it

Julian Hyde said...

Pedro,

I always liked the way Oracle does it. Oracle does it both ways: you can get the plan interactively by typing 'EXPLAIN PLAN FOR ', or Oracle will write the plan for every statement executed to the log.

(I didn't like the fact that Oracle wrote the results of EXPLAIN PLAN into a table, and then you'd have to write a complicated query to get it out again. We plan to skip that part.)

Profiling only makes sense in the second case, where you are actually executing the query, and therefore have some timings to attach to each node in the plan.

What works for SQL works for MDX also, and we'd probably do both too. If we had to work in strict order of priority, I'd be inclined to put the plan into the log before I implemented the EXPLAIN PLAN command.

Julian

Anonymous said...

Hello,

I'm actually working the very last version and i would need to
trace the SQL queries generated from the MDX. I know that you worked on an
explain method of the class Query which actually trace the execution plan
of Mondrian but still, as far i have understood, does not allow the
visualization of the SQL queries. Is that correct? How to get the list of
SQL queries WITHOUT executing the MDX plan (i know that sql can be retrieved from the execution logs of mondrian)?

Thank you!

Julian Hyde said...

Anonymous,

There is no way to see the SQL without executing the MDX. The mapping between MDX and SQL is not simple. Mondrian executes an MDX query, looks first in the cache for the information it needs, then generates SQL for what is missing. If there are complex calculations, it may need to go back to the database several times.

Julian

Landon Kuhn said...

I'm looking for an update on this discussion. Has any progress being made in the area of query cost analysis?

Julian Hyde said...

As you can see, http://jira.pentaho.com/browse/MONDRIAN-754 is still unresolved. You can vote for it.