def test_start_with_unfinished_action_fails(self):
# A design constraint of timeline says that overlapping actions are not
# permitted. See the Timeline docstrings.
timeline = Timeline()
action = timeline.start("Sending mail", "Noone")
self.assertRaises(OverlappingActionError, timeline.start,
"Sending mail", "Noone")
def test_nested_start_is_not_transitive(self):
# nesting is explicit at each level - not inherited.
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
child = timeline.start("SQL Callback", "SELECT...")
self.assertRaises(OverlappingActionError, timeline.start,
"Sending mail", "Noone")
def test_multiple_nested_children_permitted(self):
# nesting is not reset by each action that is added.
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
child = timeline.start("SQL Callback", "SELECT...")
child.finish()
child = timeline.start("SQL Callback", "SELECT...")
def test_start_after_finish_works(self):
timeline = Timeline()
action = timeline.start("Sending mail", "Noone")
action.finish()
action = timeline.start("Sending mail", "Noone")
action.finish()
self.assertEqual(2, len(timeline.actions))
def test_start_sets_backtrace_by_default(self):
timeline = Timeline()
action = timeline.start("Sending mail", "Noone")
self.assertNotEqual(None, action.backtrace)
self.assertIsInstance(action.backtrace, str)
self.assertThat(action.backtrace,
EndsWith(' action = timeline.start("Sending mail", "Noone")\n'))
def test_nested_category_labels(self):
# To identify start/stop pairs '-start' and '-stop' are put onto the
# category of nested actions:
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
action.finish()
self.assertEqual('Calling openid-start', timeline.actions[0].category)
self.assertEqual('Calling openid-stop', timeline.actions[1].category)
def test_multiple_starts_after_nested_group_prevented(self):
# nesting stops being permitted when the nesting action is finished.
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
action.finish()
child = timeline.start("SQL Callback", "SELECT...")
self.assertRaises(OverlappingActionError, timeline.start,
"Sending mail", "Noone")
def test_start_returns_action(self):
timeline = Timeline()
action = timeline.start("Sending mail", "Noone")
self.assertIsInstance(action, TimedAction)
self.assertEqual("Sending mail", action.category)
self.assertEqual("Noone", action.detail)
self.assertEqual(None, action.duration)
self.assertEqual(timeline, action.timeline)
def test_nested_actions_recorded_as_two_zero_length_actions(self):
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
child = timeline.start("SQL Callback", "SELECT...")
child.finish()
action.finish()
self.assertEqual(3, len(timeline.actions))
self.assertEqual(datetime.timedelta(), timeline.actions[0].duration)
self.assertEqual(datetime.timedelta(), timeline.actions[2].duration)
def test_trim(self):
timeline = Timeline()
timeline.append(Event(body='created', _at=1408628762))
timeline.append(Event(body='processed', _at=1408628769))
timeline.append(Event(body='ended', _at=1408628778))
timeline.trim(2)
assert len(timeline) == 2
assert timeline[0]['body'] == 'processed'
assert timeline[0]._at == 1408628769
def test_session_queries_filtered(self):
"""Test that session queries are filtered."""
utility = ErrorReportingUtility()
del utility._oops_config.publishers[:]
timeline = Timeline()
timeline.start("SQL-session", "SELECT 'gone'").finish()
try:
raise ArbitraryException('foo')
except ArbitraryException:
info = sys.exc_info()
oops = utility._oops_config.create(
dict(exc_info=info, timeline=timeline))
self.assertEqual("SELECT '%s'", oops['timeline'][0][3])
def test_session_queries_filtered(self):
"""Test that session queries are filtered."""
utility = ErrorReportingUtility()
utility._oops_config.publisher = None
timeline = Timeline()
timeline.start("SQL-session", "SELECT 'gone'").finish()
try:
raise ArbitraryException('foo')
except ArbitraryException:
info = sys.exc_info()
oops = utility._oops_config.create(
dict(exc_info=info, timeline=timeline))
self.assertEqual("SELECT '%s'", oops['timeline'][0][3])
def test_timeframe(self):
timeline = Timeline()
timeline.append(Event(body='created', _at=1408628762))
timeline.append(Event(body='processed', _at=1408628769,
_until=1408628779))
timeline.append(Event(body='ended', _at=1408628778))
assert timeline.timeframe() == Timeframe(1408628762, 1408628779)
def test_last_consecutive(self):
timeline = Timeline()
timeline.append(Event(body='created', _at=1408628762))
timeline.append(Event(body='processed', _at=1408628769))
timeline.append(Event(body='ended', _at=1408628778))
test = timeline.last(lambda x: x._at <= 1408628769)
assert len(test) == 0
test = timeline.last(lambda x: x._at > 1408628762)
assert len(test) == 2
assert test[0]._at == 1408628769
assert test[0]['body'] == 'processed'
def test_deserialize(self):
serialized = ('[{"_at":1408628700, "body": "step1"}, '
'{"_at":1408628700, "body": "step2"}]')
timeline = Timeline.from_json(serialized)
assert len(timeline) == 2
assert timeline[-1]['body'] == 'step2'
assert timeline[-1]._at == 1408628700
def test_logTupleBacktrace(self):
# If the action has a backtrace attribute, that is placed into the
# fifth element of logTuple.
timeline = Timeline()
action = TimedAction("foo", "bar", timeline)
action.finish()
action.backtrace = "Foo Bar"
log_tuple = action.logTuple()
self.assertEqual("Foo Bar", log_tuple[4])
def test_project(self):
timeline = Timeline()
timeline.append(Event(body='created', _at=1408628762,
timeframe=[4, 5]))
timeline.append(Event(body='processed', _at=1408628769,
timeframe=[7, 8]))
timeline.append(Event(body='ended', _at=1408628778,
timeframe=[10, 50]))
projected = timeline.project(lambda x: x['timeframe'])
assert projected[0]._at == 4
assert projected[1]._until == 8
def set_request_started(starttime=None,
request_statements=None,
txn=None,
enable_timeout=True):
"""Set the start time for the request being served by the current
thread.
:param start_time: The start time of the request. If given, it is used as
the start time for the request, as returned by time(). If it is not
given, the current time is used.
:param request_statements; The sequence used to store the logged SQL
statements.
:type request_statements: mutable sequence.
:param txn: The current transaction manager. If given, txn.commit() and
txn.abort() calls are logged too.
:param enable_timeout: If True, a timeout error is raised if the request
runs for a longer time than the configured timeout.
"""
if getattr(_local, 'request_start_time', None) is not None:
warnings.warn(
'set_request_started() called before previous request '
'finished',
stacklevel=1)
if starttime is None:
starttime = time()
_local.request_start_time = starttime
request = get_current_browser_request()
if request_statements is not None:
# Specify a specific sequence object for the timeline.
set_request_timeline(request, Timeline(request_statements))
else:
# Ensure a timeline is created, so that time offset for actions is
# reasonable.
set_request_timeline(request, Timeline())
_local.current_statement_timeout = None
_local.enable_timeout = enable_timeout
_local.commit_logger = CommitLogger(transaction)
transaction.manager.registerSynch(_local.commit_logger)
def test_timeline_iterate():
"""
Create a timeline with 3 events and check that we can iterate over them correcly
"""
event1 = Event("1", "1978", "__")
event2 = Event("2", "1 Sep 1997", "31 Jul 2000")
event3 = Event("3", "01/12/1990", "31/08/1997")
timeline = Timeline([event1, event2, event3])
output = []
for event in timeline:
output.append(event)
assert output[0] == event1
assert output[1] == event3
assert output[2] == event2
def clear_request_started():
"""Clear the request timer. This function should be called when
the request completes.
"""
if getattr(_local, 'request_start_time', None) is None:
warnings.warn('clear_request_started() called outside of a request',
stacklevel=2)
_local.request_start_time = None
_local.sql_logging = None
_local.sql_logging_start = None
_local.sql_logging_tracebacks_if = None
request = get_current_browser_request()
set_request_timeline(request, Timeline())
if getattr(_local, 'commit_logger', None) is not None:
transaction.manager.unregisterSynch(_local.commit_logger)
del _local.commit_logger
def test_logTupleIncomplete(self):
# Things that start and hit a timeout *may* not get recorded as
# finishing in normal operation - they still need to generate a
# logTuple, using now as the end point.
timeline = Timeline()
action = TimedAction("foo", "bar", timeline)
# Set variable for deterministic results
action.start = timeline.baseline + datetime.timedelta(0, 0, 0, 2)
action._interval_to_now = lambda: datetime.timedelta(0, 0, 0, 3)
log_tuple = action.logTuple()
self.assertEqual(5, len(log_tuple), "!= 5 elements %s" % (log_tuple, ))
self.assertIsInstance(log_tuple[0], int)
self.assertEqual(2, log_tuple[0])
self.assertIsInstance(log_tuple[1], int)
self.assertEqual(5, log_tuple[1])
self.assertEqual("foo", log_tuple[2])
self.assertEqual("bar", log_tuple[3])
def test_logTuple(self):
timeline = Timeline()
action = TimedAction("foo", "bar", timeline)
# Set variable for deterministic results
action.start = timeline.baseline + datetime.timedelta(0, 0, 0, 2)
action.duration = datetime.timedelta(0, 0, 0, 4)
log_tuple = action.logTuple()
self.assertEqual(5, len(log_tuple), "!= 5 elements %s" % (log_tuple, ))
# The first element is the start offset in ms.
self.assertIsInstance(log_tuple[0], int)
self.assertEqual(2, log_tuple[0])
# The second element is the end offset in ms.
self.assertIsInstance(log_tuple[1], int)
self.assertEqual(6, log_tuple[1])
self.assertEqual("foo", log_tuple[2])
self.assertEqual("bar", log_tuple[3])
# The fifth element defaults to None:
self.assertEqual(None, log_tuple[4])
def test_nesting_within_nesting_permitted(self):
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
middle = timeline.start("Calling otherlibrary", "", allow_nested=True)
child = timeline.start("SQL Callback", "SELECT...")
def graph_package_deps(self, p, pngname):
tl = Timeline()
def epoch(t): return t.toordinal() #float(t.strftime("%s"))
def authColor(p): return hashColor(self.author(p))
#depbar = "LightSkyBlue"
#focalbar = "Yellow"
reflbar = "PaleGoldenrod"
vers_names = self.versions(p)
# extend each version until the end of hte subsequent version
for v,w in zip(vers_names[:-1], vers_names[1:]): # Lost author for author color
tl.span(p, epoch(self.dc[p][v]), epoch(self.dc[p][w]), p + ":" + v, v, authColor(p), None)
vlast = vers_names[-1]
tl.span(p, epoch(self.dc[p][vlast]), epoch(self.end_of_time), p + ":" + vlast, vlast, authColor(p), None)
for dep in self.dependencies(p):
for (ref,st,en) in self.dep_version_spans(p, dep):
tl.span(dep, epoch(st), epoch(en), dep + "::" + ref, ref, reflbar, "bottom")
depvers = self.dep_versions(p, dep)
try:
vn2 = self.versions(dep)
for vv,ww in zip(vn2[:-1], vn2[1:]):
self.logwith( "deploop", vv,ww, self.dc[dep].keys())
tl.span(dep, epoch(self.dc[dep][vv]), epoch(self.dc[dep][ww]),
dep + ":" + vv, vv, authColor(dep), "top")
vvlast = vn2[-1]
tl.span(dep, epoch(self.dc[dep][vvlast]), epoch(self.end_of_time),
dep + ":" + vvlast, vvlast, authColor(dep), "top")
except Exception, e:
self.logwith("Exception processing dependency", dep, e)
for vn in vers_names:
if vn in depvers:
dep_ver = self.extractVersionLimiter(depvers[vn])
self.logwith( dep_ver)
destrec = tl.findByKey(dep + ":" + dep_ver)
srcrec = tl.findByKey(p + ":" + vn)
if len(destrec) > 0 and len(srcrec) > 0:
tl.connect(destrec[0], srcrec[0])
self.logwith( "version", vn, "of", p, "did link to dependency", dep, "version", dep_ver)
else:
self.logwith( "version", vn, "of", p, "***can't*** find dependency", \
dep, "version", dep_ver, "lendestrec=", len(destrec), "lensrcrec=", len(srcrec))
else:
self.logwith(vn,"is not in",list(depvers))
self.logwith( "version", vn, "of", p, "did not update dependency on", dep)
def test_set_timeline(self):
req = TestRequest()
timeline = Timeline()
set_request_timeline(req, timeline)
self.assertEqual(timeline, get_request_timeline(req))
def graph_package_downstreams(self, p, pngname):
tl = Timeline()
def epoch(t): return t.toordinal() #float(t.strftime("%s"))
def authColor(p): return hashColor(self.author(p))
reflbar = "PaleGoldenrod"
vers_names = self.versions(p)
# Just show the first 20; the image gets too big otherwise
for dep in list(self.reverse_dependencies(p))[:20]:
for (ref,st,en) in self.dep_version_spans(dep, p):
try:
vname = str(ref).strip()
if vname == "": vname = "*"
except:
self.logwith("Could not correct version name ", ref)
vname = ref
tl.span(dep, epoch(st), epoch(en), dep + "::" + ref, "-->" + vname, reflbar, "bottom", invisibleBar=True)
depvers = self.dep_versions(dep, p)
try:
vn2 = self.versions(dep)
for vv,ww in zip(vn2[:-1], vn2[1:]):
self.logwith( "deploop", vv,ww, self.dc[dep].keys())
tl.span(dep, epoch(self.dc[dep][vv]), epoch(self.dc[dep][ww]),
dep + ":" + vv, vv, authColor(dep), "top")
vvlast = vn2[-1]
tl.span(dep, epoch(self.dc[dep][vvlast]), epoch(self.end_of_time),
dep + ":" + vvlast, vvlast, authColor(dep), "top")
except Exception, e:
self.logwith("Exception processing dependency", dep, e)
for vn in vers_names:
if vn in depvers:
dep_ver = self.extractVersionLimiter(depvers[vn])
self.logwith( dep_ver)
destrec = tl.findByKey(dep + ":" + dep_ver)
srcrec = tl.findByKey(p + ":" + vn)
if len(destrec) > 0 and len(srcrec) > 0:
tl.connect(destrec[0], srcrec[0])
self.logwith( "version", vn, "of", p, "did link to dependency", dep, "version", dep_ver)
else:
self.logwith( "version", vn, "of", p, "***can't*** find dependency", \
dep, "version", dep_ver, "lendestrec=", len(destrec), "lensrcrec=", len(srcrec))
else:
self.logwith(vn,"is not in",list(depvers))
self.logwith( "version", vn, "of", p, "did not update dependency on", dep)
def test_baseline(self):
timeline = Timeline()
self.assertIsInstance(timeline.baseline, datetime.datetime)
def test_backtraces_can_be_disabled(self):
# Passing format_stack=None to Timeline prevents backtrace gathering.
timeline = Timeline(format_stack=None)
action = timeline.start("Sending mail", "Noone")
self.assertEqual(None, action.backtrace)
def test_map(self):
expected = Timeline()
expected.append(Event(body='created', _at=1408628762))
expected.append(Event(body='processed', _at=1408628769))
expected.append(Event(body='ended', _at=1408628778))
to_map = Timeline()
to_map.append(Event(a=1, body='created', _at=1408628762))
to_map.append(Event(a=2, body='processed', _at=1408628769))
to_map.append(Event(a=3, body='ended', _at=1408628778))
mapped = to_map.map(lambda x: {'body': x['body']})
assert mapped == expected
def test_can_supply_list(self):
actions = "foo"
timeline = Timeline(actions)
self.assertEqual(actions, timeline.actions)
def test_serialize(self):
timeline = Timeline()
timeline.append(Event(body='created', _at=1408628762))
timeline.append(Event(body='processed', _at=1408628769))
assert str(timeline) == ('[{"body": "created", "_at": 1408628762}, '
'{"body": "processed", "_at": 1408628769}]')
def test_nested_start_permitted(self):
# When explicitly requested a nested start can be done
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
child = timeline.start("SQL Callback", "SELECT...")
def test_finish_adds_action(self):
timeline = Timeline()
action = NestingTimedAction("Sending mail", None, timeline)
action.finish()
self.assertEqual(1, len(timeline.actions))
self.assertEqual(datetime.timedelta(), timeline.actions[-1].duration)
def test_finishing_nested_within_nested_leaves_outer_nested_nesting(self):
timeline = Timeline()
action = timeline.start("Calling openid", "hostname", allow_nested=True)
middle = timeline.start("Calling otherlibrary", "", allow_nested=True)
middle.finish()
child = timeline.start("SQL Callback", "SELECT...")
def visualize():
"""
Visualize route
"""
if request.method == "GET":
choose_data = config.get_datafiles()
return render_template("visualize.html", choose_data=choose_data)
elif request.method == "POST":
try:
shutil.rmtree("static/visualize")
print(">>> Removed folder: visualized")
except Exception as e:
print("No such folder: ", e)
data_for_timeline = collections.OrderedDict()
month_names = []
hotspots = []
hotspot = {}
conflevel = request.form["setupConfidenceLevel"]
months = calendar.month_name
dates = [
"", "2014-01", "2014-02", "2014-03", "2014-04", "2014-05",
"2014-06", "2014-07", "2014-08", "2014-09", "2014-10", "2014-11",
"2014-12"
]
empty_hotspots = []
splitted_months = functions.split_csv(request.form["setupData"])
for mon in range(1, 13):
hotspot = Visual(request.form["setupData"], months[mon], conflevel,
units)
hotspot.getis, hotspot.conf_levels = functions.calculate_hotspot(
hotspot, splitted_months[mon - 1]["data"], "getis")
data_for_timeline[months[mon]] = hotspot.getis
functions.save_csv(hotspot.getis, "static/visualize/",
hotspot.title, ".csv")
# Creates the getis hotspot
getis_hotspot = functions.create_hotspot(hotspot, "getis_visual",
hotspot.pvalue)
# Save getis hotspot as png
functions.save_figure(getis_hotspot, "static/visualize/",
hotspot.title, ".png")
month_names.append(months[mon])
# hotspots.append(hotspot)
# Timeline takes a list of dataFrames
timeline = Timeline(data_for_timeline)
timeline.calculate_total()
timeline.calculate_percentage()
timeline_result = timeline.create_timeline()
functions.save_figure(timeline_result, "static/visualize/", "timeline",
".png")
return render_template("visualize.html",
months=month_names,
csvfile=request.form["setupData"],
conf=conflevel,
time="?" + str(time.time()))
