Dear Martin and Stefan,

As Martin mentioned, the *usec* value of *start* event for MAL instructions depends on whether it is the first-time execution in current session.

For the first-time execution, the output is as follows:
===================================
...
[ 91, "user.s1_5[45]175", 3, "start", 0, 828, 0, 0, 0, 0, 0, 0, "X_35=nil:bat[:int] := algebra.projectionpath(r1_27=<tmp_2705>[7194884]:bat[:oid],C_2=<tmp_2710>[7194884]:bat[:oid],X_34=<tmp_2135>[7197566]:bat[:int]);" ]
[ 92, "user.s1_5[45]175", 3, "done ", 189672, 883, 137, 0, 56216, 1, 0, 50, "X_35=<tmp_2702>[7194884]:bat[:int] := algebra.projectionpath(r1_27=<tmp_2705>[7194884]:bat[:oid],C_2=<tmp_2710>[7194884]:bat[:oid],X_34=<tmp_2135>[7197566]:bat[:int]);" ]
[ 93, "user.s1_5[46]175", 3, "start", 0, 883, 0, 0, 0, 0, 0, 0, "X_36=nil:bat[:int] := sql.bind(X_1=0:int,\"sys\":str,\"web_sales\":str,\"ws_order_number\":str,0:int);" ]
[ 94, "user.s1_5[46]175", 3, "done ", 62, 883, 0, 0, 0, 0, 0, 0, "X_36=<tmp_421>[7197566]:bat[:int] := sql.bind(X_1=0:int,\"sys\":str,\"web_sales\":str,\"ws_order_number\":str,0:int);" ]
...
===================================

For the second-time execution, the output is as follows:
===================================
...
[ 91, "user.s1_5[45]180", 3, "start", 189672, 883, 137, 0, 0, 0, 0, 0, "X_35=nil:bat[:int] := algebra.projectionpath(r1_27=<tmp_2710>[7194884]:bat[:oid],C_2=<tmp_2704>[7194884]:bat[:oid],X_34=<tmp_2135>[7197566]:bat[:int]);" ]
[ 92, "user.s1_5[45]180", 3, "done ", 185919, 911, 274, 0, 56216, 1, 0, 46, "X_35=<tmp_2713>[7194884]:bat[:int] := algebra.projectionpath(r1_27=<tmp_2710>[7194884]:bat[:oid],C_2=<tmp_2704>[7194884]:bat[:oid],X_34=<tmp_2135>[7197566]:bat[:int]);" ]
[ 93, "user.s1_5[46]180", 3, "start", 62, 911, 0, 0, 0, 0, 0, 0, "X_36=nil:bat[:int] := sql.bind(X_1=0:int,\"sys\":str,\"web_sales\":str,\"ws_order_number\":str,0:int);" ]
[ 94, "user.s1_5[46]180", 3, "done ", 37, 911, 0, 0, 0, 0, 0, 0, "X_36=<tmp_421>[7197566]:bat[:int] := sql.bind(X_1=0:int,\"sys\":str,\"web_sales\":str,\"ws_order_number\":str,0:int);" ]
...
====================================

So,
-- for the first-time execution, the *usec* value of *start* event for an MAL instruction is always 0.
-- for subsequent execution, that value is the average *usec* of *done* event w.r.t. that instruction over all historical executions.

Best regards,
Wenjian


On Fri, Aug 5, 2016 at 5:03 PM, Martin Kersten <martin.kersten@cwi.nl> wrote:
        // determine the Estimated Time of Completion
        if ( pci->calls){
            logadd("\"usec\":"LLFMT",%s", pci->totticks/pci->calls, prettify);
        } else{
            logadd("\"usec\":"LLFMT",%s", pci->ticks, prettify);
        }

Running the same MAL procedure leads to accumulated timings,
which provides an indication how long a MAL instruction is likely to take.

On 05/08/16 10:56, Stefan Manegold wrote:
Wenjian,

Afaik, the used value with start events should always be 0. Let us know if not.

Stefan


On August 5, 2016 8:23:31 AM CEST, "Xu,Wenjian" <zeroxwj@gmail.com> wrote:

    Hi Moritz,

    Thanks a lot for your help.

    I have tried *stethscope*. When I looked at the output, I understand that entries with *done* state display the actual time needed for execution. But what about the entries with *start* state? What does *usec* refer to in those entries?

    Best regards,
    Wenjian

     On Thu, Aug 4, 2016 at 9:17 PM, Moritz Bruder <moritz.bruder@student.uni-tuebingen.de <mailto:moritz.bruder@student.uni-tuebingen.de>> wrote:

        Hi,

            Hi all,

            MonetDB version: 11.23.7
            Ubuntu version: 14.04

            How could I obtain the running time information in the MAL interface of
            mclient? I tried to use the *--interactive* option but it did not work.

        I think what you're looking for is *stethoscope*.

            I would like to obtain the running time information after getting the
            result of that query. How can I do it?

        Start *stethoscope* and connect it to the same database, run your query. It should now show the needed execution time for every instruction while you run it (entries with *done* state display the actual time needed for execution), and additionally
        you will see the complete time for your function at the end. Works for both languages I use (*mal* and *sql*).

        Further information: https://www.monetdb.org/Documentation/Manuals/MonetDB/Profiler/Stethoscope


        Regards,

        Moritz
        _______________________________________________
        users-list mailing list
         users-list@monetdb.org <mailto:users-list@monetdb.org>
        https://www.monetdb.org/mailman/listinfo/users-list


    ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

    users-list mailing list
    users-list@monetdb.org
    https://www.monetdb.org/mailman/listinfo/users-list


--
| Stefan.Manegold@CWI.nl | DB Architectures (DA) |
 | www.CWI.nl/~manegold <http://www.CWI.nl/~manegold>/ | Science Park 123 (L321) |
| +31 (0)20 592-4212 | 1098 XG Amsterdam (NL) |


 _______________________________________________
users-list mailing list
users-list@monetdb.org
https://www.monetdb.org/mailman/listinfo/users-list


_______________________________________________
users-list mailing list
users-list@monetdb.org
https://www.monetdb.org/mailman/listinfo/users-list