Add time attribute in trace.

[Ezibenroc]

Each module should provide the total running time it takes to answer the query. It will help us to know precisely what takes time and should be optimized.

[progval]

Should the time be measured by the module or the caller of the module? The latter counts network latency, the former doesn't.

[marc-chevalier]

I think the caller has to time the module. Indeed, network latency is a part of the time spent in the module, which is relevant. Especially if the module returns a large amount of data. Deploy a module on a server which has a greater bandwidth is a optimisation and, in some case, it may be the solution. In the same idea, the time in which we are interested is the real time between the begin and the end. Not the CPU time. Indeed a CPU time can be small but the real time much greater if the CPU is very loaded. For these reason, I think the measure has to be "extern". Moreover, it will be the same code to measure the time in each module and I don't think the module's developper has to do that (except if there is a totally hidden way in which the dev has nothing to do, maybe via the libmodule). And, last, if the dev has to time his own module, he can lie, for example by considering that a part of the work has to be not time, and make this field totally useless.

The time spent in the module itself is only a part of the total time and says only if the module can be make faster. It's a "local" information which does not mean something for the global architecture. But if the developper wants to know the time spent in some functions of his module, he can log it in a file which will be usefull only for him.

[progval]

except if there is a totally hidden way in which the dev has nothing to do, maybe via the libmodule

obviously

And, last, if the dev has to time his own module, he can lie, for example by considering that a part of the work has to be not time, and make this field totally useless.

For the moment, we totally trust modules. It's easy for any module to make a core worker crash.

I agree with everything else, though.

[Ezibenroc]

I agree that it is important to take into account the time spent in communications.

But, if each module measure its total time (thus excluding communication) and send it to its caller, then the caller can deduce the time spent on the module and the time spent on communication.

If only the caller measure the time, we only know the global time: there is a lack of precision.

To go further, we could add details to this time information. As @s-i-newton suggested, the real time and the CPU time are important if we want to know if a module is CPU-bound or I/O-bound. We could provide both these times.

We could even be interested in module-specific details, such as the time spent on several relevant part of the code. For instance, the Grammatical module could return something like:

{
    "preprocessing" : 0.002,
    "stanford library" : 0.23,
    "nounification" : 0.015,
    "normalization" : 0.008
}

But a log file may be better than the trace for these details.

[marc-chevalier]

Indeed, I do not see why it will be relevant to store time in the trace. The trace is made to be an historic for other module (and debugging when the path is complicated and cause odd answer). An independent log file is maybe more suitable, and in this case, we can log everything we want: total time, module time and potentially everything that the module's dev. wants to know.

[Ezibenroc]

It depends. The time spent on several code's parts of a module is a local information, it does not make sense to compare it with the other module's times. Thus, it should be saved in a log file. On the other hand, the total execution time of a module does not mean anything if we do not compare it with the other modules. Doing this comparison could be tedious if we also save this in a log file. It would be much easier if all is centralized in the trace.

So here is what I propose. The callee save the following in the trace:

{ "time" : {
             "cpu" : <cpu time>
             "real" : <real time>
}}

Then, the caller modifies this piece of the trace to add the communication time (obtained via a substraction):

{ "time" : {
             "cpu" : <cpu time>
             "real" : <real time>
             "communication" : <communication time>
}}

Then we could save it in some database.

We should provide a standard way to measure time, to have consistent measures. For instance, all modules written in a same language should use the exact same function for the measure.

[Ezibenroc]

I modified the time to have the three atributes: cpu, real and communication.

[Ezibenroc]

Any thought about this? If you agree, maybe we could merge?

[Tpt]

Looks good for me.

[marc-chevalier]

I'm still not convinced the trace is the right place for time log. Whatever, I agree to merge.

[Ezibenroc]

By doing so, all the information is contained in the trace, it will be easier to analyze. Moreover, if for some reason a module is running on a separate machine, it will still work thanks to HTTP. If we logged the times in files, it would be trickier. I do not see any reason to put these time logs in an other place than the trace.

[marc-chevalier]

Everybody seems agree.