Commit b9b5abcb authored by Iustin Pop's avatar Iustin Pop
Browse files

Add a new opcode timestamp field



Since the current start_timestamp opcode attribute refers to the inital
start time, before locks are acquired, it's not useful to determine the
actual execution order of two opcodes/jobs competing for the same lock.

This patch adds a new field, exec_timestamp, that is updated when the
opcode moves from OP_STATUS_WAITLOCK to OP_STATUS_RUNNING, thus allowing
a clear view of the execution history. The new field is visible in the
job output via the 'opexec' field.
Signed-off-by: default avatarIustin Pop <iustin@google.com>
Reviewed-by: default avatarGuido Trotter <ultrotter@google.com>
parent 14aeab22
......@@ -77,11 +77,12 @@ class _QueuedOpCode(object):
@ivar status: the current status
@ivar result: the result of the LU execution
@ivar start_timestamp: timestamp for the start of the execution
@ivar exec_timestamp: timestamp for the actual LU Exec() function invocation
@ivar stop_timestamp: timestamp for the end of the execution
"""
__slots__ = ["input", "status", "result", "log",
"start_timestamp", "end_timestamp",
"start_timestamp", "exec_timestamp", "end_timestamp",
"__weakref__"]
def __init__(self, op):
......@@ -96,6 +97,7 @@ class _QueuedOpCode(object):
self.result = None
self.log = []
self.start_timestamp = None
self.exec_timestamp = None
self.end_timestamp = None
@classmethod
......@@ -114,6 +116,7 @@ class _QueuedOpCode(object):
obj.result = state["result"]
obj.log = state["log"]
obj.start_timestamp = state.get("start_timestamp", None)
obj.exec_timestamp = state.get("exec_timestamp", None)
obj.end_timestamp = state.get("end_timestamp", None)
return obj
......@@ -130,6 +133,7 @@ class _QueuedOpCode(object):
"result": self.result,
"log": self.log,
"start_timestamp": self.start_timestamp,
"exec_timestamp": self.exec_timestamp,
"end_timestamp": self.end_timestamp,
}
......@@ -385,6 +389,7 @@ class _OpExecCallbacks(mcpu.OpExecCbBase):
raise CancelJob()
self._op.status = constants.OP_STATUS_RUNNING
self._op.exec_timestamp = TimeStampNow()
finally:
self._queue.release()
......@@ -1383,6 +1388,8 @@ class JobQueue(object):
row.append([op.log for op in job.ops])
elif fname == "opstart":
row.append([op.start_timestamp for op in job.ops])
elif fname == "opexec":
row.append([op.exec_timestamp for op in job.ops])
elif fname == "opend":
row.append([op.end_timestamp for op in job.ops])
elif fname == "received_ts":
......
......@@ -210,7 +210,15 @@
<varlistentry>
<term>opstart</term>
<listitem>
<simpara>the list of opcode start times</simpara>
<simpara>the list of opcode start times (before
acquiring locks)</simpara>
</listitem>
</varlistentry>
<varlistentry>
<term>opexec</term>
<listitem>
<simpara>the list of opcode execution start times (after
acquiring any necessary locks)</simpara>
</listitem>
</varlistentry>
<varlistentry>
......
......@@ -80,6 +80,7 @@ def ListJobs(opts, args):
"oplog": "OpCode_log",
"summary": "Summary",
"opstart": "OpCode_start",
"opexec": "OpCode_exec",
"opend": "OpCode_end",
"start_ts": "Start",
"end_ts": "End",
......@@ -106,7 +107,7 @@ def ListJobs(opts, args):
val = ",".join(val)
elif field in ("start_ts", "end_ts", "received_ts"):
val = FormatTimestamp(val)
elif field in ("opstart", "opend"):
elif field in ("opstart", "opexec", "opend"):
val = [FormatTimestamp(entry) for entry in val]
elif field == "lock_status" and not val:
val = "-"
......@@ -212,7 +213,7 @@ def ShowJobs(opts, args):
selected_fields = [
"id", "status", "ops", "opresult", "opstatus", "oplog",
"opstart", "opend", "received_ts", "start_ts", "end_ts",
"opstart", "opexec", "opend", "received_ts", "start_ts", "end_ts",
]
result = GetClient().QueryJobs(args, selected_fields)
......@@ -235,7 +236,7 @@ def ShowJobs(opts, args):
continue
(job_id, status, ops, opresult, opstatus, oplog,
opstart, opend, recv_ts, start_ts, end_ts) = entry
opstart, opexec, opend, recv_ts, start_ts, end_ts) = entry
format(0, "Job ID: %s" % job_id)
if status in _USER_JOB_STATUS:
status = _USER_JOB_STATUS[status]
......@@ -275,14 +276,18 @@ def ShowJobs(opts, args):
else:
format(1, "Total processing time: N/A")
format(1, "Opcodes:")
for (opcode, result, status, log, s_ts, e_ts) in \
zip(ops, opresult, opstatus, oplog, opstart, opend):
for (opcode, result, status, log, s_ts, x_ts, e_ts) in \
zip(ops, opresult, opstatus, oplog, opstart, opexec, opend):
format(2, "%s" % opcode["OP_ID"])
format(3, "Status: %s" % status)
if isinstance(s_ts, (tuple, list)):
format(3, "Processing start: %s" % FormatTimestamp(s_ts))
else:
format(3, "No processing start time")
if isinstance(x_ts, (tuple, list)):
format(3, "Execution start: %s" % FormatTimestamp(x_ts))
else:
format(3, "No execution start time")
if isinstance(e_ts, (tuple, list)):
format(3, "Processing end: %s" % FormatTimestamp(e_ts))
else:
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment