The environment comprises a dual Xeon E5-2680 CPU server clocked at 2.7 GHz running Ubuntu (12.10, I believe) x86_64 SMP Linux (3.5.0-17-generic kernel).  /proc/cpuinfo reports that there are 32 CPUs, so I presume there are 16 cores in each CPU (or perhaps eight cores each with hyperthreading?).  The machine has 198,062,144 KBytes of RAM according to /proc/meminfo (a strange number, admittedly).  We're running a very slightly modified Feb2013-SP1 MonetDB system; however, none of the modifications relate to performance.  (They relate to generating enough type information that we can automatically run explain-generated MAL.)

The observation is that (consistently), when running TPCH Query 1 in MAL from mclient while tracing output via stethoscope, we see that the last event noted by stethoscope, i.e., sql.exportResult() completes about 10-15 seconds before mclient displays its results.  And sql.exportResult() is the final MAL instruction in the program.  (Well, that's not quite true.  The program is run by calling the MAL function generated by explaining a SQL query, so I suppose there is a return from the function call.  And we call sql.init() before calling the function.)

We are ssh'ed into the system, and we are running in an LXC container, in case either of those might make a difference.  But for the case in which we run SQL, we are also ssh'ed into an LXC container.  And the results are consistently repeatable.

I just tried setting all sorts of flags in stethoscope, but once it shows that sql.exportResult() has completed, I get no more output from it.  The next thing that happens is that mclient returns its results (some 10-15 seconds later).

Is mclient performing some sort of complex computation on the results prior to displaying them?  Or is there some complex protocol between mserver and mclient in the case of MAL queries?  (It's unlikely to be paging, due to the large amount of RAM.)  There should be no other activity going on in the system.

In the case of SQL queries, we get the results approximately simultaneously with stethoscope noting that sql.exportResult() has finished.

I wonder whether you can think of something that we might be doing wrong or whether you can give us some idea what is happening in those 10-15 seconds?

Thank you,

Steve

--- On Mon, 5/20/13, Martin Kersten <Martin.Kersten@cwi.nl> wrote:

From: Martin Kersten <Martin.Kersten@cwi.nl>
Subject: Re: Using something like "trace" within the MAL interpreter
To: users-list@monetdb.org
Date: Monday, May 20, 2013, 12:11 PM

Hi.
Thank you for the comments. Overall there is no immediate answer to your
question, because the Mserver, OS and hardware characteristics are
unkown.
On a small (ATOM) system there may be swapping between client/server
cost, or network-re-establishment cost in a distributed client/server
(cloud) setup.

Also some Linux versions show unstable behavior under some page
mapping schemes.

On 5/20/13 7:11 PM, Stephen P. Morgan wrote:
> Hi. I'm working with Masood.  When profiling an explained (MAL) version
> of TPCH Query 1 with stethoscope, we noticed something strange, and
> would appreciate your comments.  First, the MAL program seems to take
> longer by about 75% (10 to 15 seconds on a given server) to produce
> output when run at TPCH scale factor 100.  (We have similar results at
> other scale factors.)  Second, the program doesn't produce output until
> about 10-15 seconds after completing sql.exportResult() when run as MAL,
looks like a reload/re-establishment of processes.

> but does so immediately after completing sql.exportResult() when run as
> SQL.  There doesn't seem to be anything going on in that final 10-15
> second interval in the MAL program, at least according to stethoscope.
The stethoscope does not show OS behavior, but this can be triggered
using the proper parameters. See stethoscope --help, which gives you
access to the basis OS performance parameters.
> What might be happening during that time?
>
> Perhaps naively, we imagined that the MAL and SQL timings would be about
> the same.
They use the same protocol for interaction.

NOTE 1; be aware of the difference between hot and cold runs.
NOTE 2; be aware that even starting a browser at the same time on the
test machine can lead to resource (memory/cpu) fights and therefore
possible performance differences.

regards, Martin
>
> Thanks,
>
> Steve
>
> ------------------------------------------------------------------------
> *From:* Martin Kersten <Martin.Kersten@cwi.nl>
> *To:* users-list@monetdb.org
> *Sent:* Fri, May 17, 2013 5:35:50 PM
> *Subject:* Re: Using something like "trace" within the MAL interpreter
>
> Hi
>
> The best way to trace is to use the 'stethoscope'
> http://www.monetdb.org/Documentation/Manuals/MonetDB/Profiler/Stethoscope
>
> For MAL programs one can use something like:
>      profiler.activate("ISTestmrw");
>      profiler.setAll();
>      profiler.openStream();
>      profiler.start();
> ...MAL program to follow....
>      profiler.stop();
>
>
> regards, Martin
>
> On 5/18/13 2:29 AM, Masood Mortazavi wrote:
>  > Hi,
>  > The "trace" commands works well when mclient is in the SQL
> interpreter mode.
>  > How about when mclient is in MAl interpreter mode? Is there a way to use
>  > the "trace" command in this mode?
>  > Best regards,
>  > Masood
>  >
>  >
>  > _______________________________________________
>  > users-list mailing list
>  > users-list@monetdb.org <mailto:users-list@monetdb.org>
>  > http://mail.monetdb.org/mailman/listinfo/users-list
>  >
> _______________________________________________
> users-list mailing list
> users-list@monetdb.org <mailto:users-list@monetdb.org>
> http://mail.monetdb.org/mailman/listinfo/users-list
>
>
> _______________________________________________
> users-list mailing list
> users-list@monetdb.org
> http://mail.monetdb.org/mailman/listinfo/users-list
>
_______________________________________________
users-list mailing list
users-list@monetdb.org
http://mail.monetdb.org/mailman/listinfo/users-list