diff options
Diffstat (limited to 'startop/scripts/trace_analyzer')
17 files changed, 1906 insertions, 0 deletions
diff --git a/startop/scripts/trace_analyzer/lib/trace2db.py b/startop/scripts/trace_analyzer/lib/trace2db.py new file mode 100644 index 000000000000..42a33aff046d --- /dev/null +++ b/startop/scripts/trace_analyzer/lib/trace2db.py @@ -0,0 +1,355 @@ +#!/usr/bin/python3 +# Copyright (C) 2019 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import re +import sys + +from sqlalchemy import create_engine +from sqlalchemy import Column, Date, Integer, Float, String, ForeignKey +from sqlalchemy.ext.declarative import declarative_base +from sqlalchemy.orm import relationship + +from sqlalchemy.orm import sessionmaker + +import sqlalchemy + +from typing import Optional, Tuple + +_DEBUG = False # print sql commands to console +_FLUSH_LIMIT = 10000 # how many entries are parsed before flushing to DB from memory + +Base = declarative_base() + +class RawFtraceEntry(Base): + __tablename__ = 'raw_ftrace_entries' + + id = Column(Integer, primary_key=True) + task_name = Column(String, nullable=True) # <...> -> None. + task_pid = Column(String, nullable=False) + tgid = Column(Integer, nullable=True) # ----- -> None. + cpu = Column(Integer, nullable=False) + timestamp = Column(Float, nullable=False) + function = Column(String, nullable=False) + function_args = Column(String, nullable=False) + + # 1:1 relation with MmFilemapAddToPageCache. + mm_filemap_add_to_page_cache = relationship("MmFilemapAddToPageCache", + back_populates="raw_ftrace_entry") + + @staticmethod + def parse_dict(line): + # ' <...>-5521 (-----) [003] ...1 17148.446877: tracing_mark_write: trace_event_clock_sync: parent_ts=17148.447266' + m = re.match('\s*(.*)-(\d+)\s+\(([^\)]+)\)\s+\[(\d+)\]\s+([\w.]{4})\s+(\d+[.]\d+):\s+(\w+):\s+(.*)', line) + if not m: + return None + + groups = m.groups() + # groups example: + # ('<...>', + # '5521', + # '-----', + # '003', + # '...1', + # '17148.446877', + # 'tracing_mark_write', + # 'trace_event_clock_sync: parent_ts=17148.447266') + task_name = groups[0] + if task_name == '<...>': + task_name = None + + task_pid = int(groups[1]) + tgid = groups[2] + if tgid == '-----': + tgid = None + + cpu = int(groups[3]) + # irq_flags = groups[4] + timestamp = float(groups[5]) + function = groups[6] + function_args = groups[7] + + return {'task_name': task_name, 'task_pid': task_pid, 'tgid': tgid, 'cpu': cpu, 'timestamp': timestamp, 'function': function, 'function_args': function_args} + +class SchedSwitch(Base): + __tablename__ = 'sched_switches' + + id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True) + + prev_comm = Column(String, nullable=False) + prev_pid = Column(Integer, nullable=False) + prev_prio = Column(Integer, nullable=False) + prev_state = Column(String, nullable=False) + + next_comm = Column(String, nullable=False) + next_pid = Column(Integer, nullable=False) + next_prio = Column(Integer, nullable=False) + + @staticmethod + def parse_dict(function_args, id = None): + # 'prev_comm=kworker/u16:5 prev_pid=13971 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120' + m = re.match("prev_comm=(.*) prev_pid=(\d+) prev_prio=(\d+) prev_state=(.*) ==> next_comm=(.*) next_pid=(\d+) next_prio=(\d+) ?", function_args) + if not m: + return None + + groups = m.groups() + # ('kworker/u16:5', '13971', '120', 'S', 'swapper/4', '0', '120') + d = {} + if id is not None: + d['id'] = id + d['prev_comm'] = groups[0] + d['prev_pid'] = int(groups[1]) + d['prev_prio'] = int(groups[2]) + d['prev_state'] = groups[3] + d['next_comm'] = groups[4] + d['next_pid'] = int(groups[5]) + d['next_prio'] = int(groups[6]) + + return d + +class SchedBlockedReason(Base): + __tablename__ = 'sched_blocked_reasons' + + id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True) + + pid = Column(Integer, nullable=False) + iowait = Column(Integer, nullable=False) + caller = Column(String, nullable=False) + + @staticmethod + def parse_dict(function_args, id = None): + # 'pid=2289 iowait=1 caller=wait_on_page_bit_common+0x2a8/0x5f' + m = re.match("pid=(\d+) iowait=(\d+) caller=(.*) ?", function_args) + if not m: + return None + + groups = m.groups() + # ('2289', '1', 'wait_on_page_bit_common+0x2a8/0x5f8') + d = {} + if id is not None: + d['id'] = id + d['pid'] = int(groups[0]) + d['iowait'] = int(groups[1]) + d['caller'] = groups[2] + + return d + +class MmFilemapAddToPageCache(Base): + __tablename__ = 'mm_filemap_add_to_page_caches' + + id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True) + + dev = Column(Integer, nullable=False) # decoded from ${major}:${minor} syntax. + dev_major = Column(Integer, nullable=False) # original ${major} value. + dev_minor = Column(Integer, nullable=False) # original ${minor} value. + + ino = Column(Integer, nullable=False) # decoded from hex to base 10 + page = Column(Integer, nullable=False) # decoded from hex to base 10 + + pfn = Column(Integer, nullable=False) + ofs = Column(Integer, nullable=False) + + # 1:1 relation with RawFtraceEntry. + raw_ftrace_entry = relationship("RawFtraceEntry", uselist=False) + + @staticmethod + def parse_dict(function_args, id = None): + # dev 253:6 ino b2c7 page=00000000ec787cd9 pfn=1478539 ofs=4096 + m = re.match("dev (\d+):(\d+) ino ([0-9a-fA-F]+) page=([0-9a-fA-F]+) pfn=(\d+) ofs=(\d+)", function_args) + if not m: + return None + + groups = m.groups() + # ('253', '6', 'b2c7', '00000000ec787cd9', '1478539', '4096') + d = {} + if id is not None: + d['id'] = id + + device_major = d['dev_major'] = int(groups[0]) + device_minor = d['dev_minor'] = int(groups[1]) + d['dev'] = device_major << 8 | device_minor + d['ino'] = int(groups[2], 16) + d['page'] = int(groups[3], 16) + d['pfn'] = int(groups[4]) + d['ofs'] = int(groups[5]) + + return d + +class Trace2Db: + def __init__(self, db_filename: str): + (s, e) = self._init_sqlalchemy(db_filename) + self._session = s + self._engine = e + self._raw_ftrace_entry_filter = lambda x: True + + def set_raw_ftrace_entry_filter(self, flt): + """ + Install a function dict(RawFtraceEntry) -> bool + + If this returns 'false', then we skip adding the RawFtraceEntry to the database. + """ + self._raw_ftrace_entry_filter = flt + + @staticmethod + def _init_sqlalchemy(db_filename: str) -> Tuple[object, object]: + global _DEBUG + engine = create_engine('sqlite:///' + db_filename, echo=_DEBUG) + + # CREATE ... (tables) + Base.metadata.create_all(engine) + + Session = sessionmaker(bind=engine) + session = Session() + return (session, engine) + + def parse_file_into_db(self, filename: str, limit: Optional[int] = None): + """ + Parse the ftrace/systrace at 'filename', + inserting the values into the current sqlite database. + + :return: number of RawFtraceEntry inserted. + """ + return parse_file(filename, self._session, self._engine, self._raw_ftrace_entry_filter, limit) + + def parse_file_buf_into_db(self, file_buf, limit: Optional[int] = None): + """ + Parse the ftrace/systrace at 'filename', + inserting the values into the current sqlite database. + + :return: number of RawFtraceEntry inserted. + """ + return parse_file_buf(file_buf, self._session, self._engine, self._raw_ftrace_entry_filter, limit) + + + @property + def session(self): + return self._session + +def insert_pending_entries(engine, kls, lst): + if len(lst) > 0: + # for some reason, it tries to generate an empty INSERT statement with len=0, + # which of course violates the first non-null constraint. + try: + # Performance-sensitive parsing according to: + # https://docs.sqlalchemy.org/en/13/faq/performance.html#i-m-inserting-400-000-rows-with-the-orm-and-it-s-really-slow + engine.execute(kls.__table__.insert(), lst) + lst.clear() + except sqlalchemy.exc.IntegrityError as err: + # possibly violating some SQL constraint, print data here. + print(err) + print(lst) + raise + +def parse_file(filename: str, *args, **kwargs) -> int: + # use explicit encoding to avoid UnicodeDecodeError. + with open(filename, encoding="ISO-8859-1") as f: + return parse_file_buf(f, *args, **kwargs) + +def parse_file_buf(filebuf, session, engine, raw_ftrace_entry_filter, limit=None) -> int: + global _FLUSH_LIMIT + count = 0 + # count and id are not equal, because count still increases for invalid lines. + id = 0 + + pending_entries = [] + pending_sched_switch = [] + pending_sched_blocked_reasons = [] + pending_mm_filemap_add_to_pagecaches = [] + + def insert_all_pending_entries(): + insert_pending_entries(engine, RawFtraceEntry, pending_entries) + insert_pending_entries(engine, SchedSwitch, pending_sched_switch) + insert_pending_entries(engine, SchedBlockedReason, pending_sched_blocked_reasons) + insert_pending_entries(engine, MmFilemapAddToPageCache, pending_mm_filemap_add_to_pagecaches) + + # for trace.html files produced by systrace, + # the actual ftrace is in the 'second' trace-data script class. + parsing_trace_data = 0 + parsing_systrace_file = False + + f = filebuf + for l in f: + if parsing_trace_data == 0 and l == "<!DOCTYPE html>\n": + parsing_systrace_file = True + continue + if parsing_trace_data != 2 and parsing_systrace_file: + if l == ' <script class="trace-data" type="application/text">\n': + parsing_trace_data = parsing_trace_data + 1 + continue + + if parsing_systrace_file and parsing_trace_data != 2: + continue + elif parsing_systrace_file and parsing_trace_data == 2 and l == " </script>\n": + # the rest of this file is just random html + break + + # now parsing the ftrace data. + if len(l) > 1 and l[0] == '#': + continue + + count = count + 1 + + if limit and count >= limit: + break + + raw_ftrace_entry = RawFtraceEntry.parse_dict(l) + if not raw_ftrace_entry: + print("WARNING: Failed to parse raw ftrace entry: " + l) + continue + + if not raw_ftrace_entry_filter(raw_ftrace_entry): + # Skip processing raw ftrace entries that don't match a filter. + # This is an optimization for when Trace2Db is used programatically + # to avoid having an overly large database. + continue + + pending_entries.append(raw_ftrace_entry) + id = id + 1 + + if raw_ftrace_entry['function'] == 'sched_switch': + sched_switch = SchedSwitch.parse_dict(raw_ftrace_entry['function_args'], id) + + if not sched_switch: + print("WARNING: Failed to parse sched_switch: " + l) + else: + pending_sched_switch.append(sched_switch) + + elif raw_ftrace_entry['function'] == 'sched_blocked_reason': + sbr = SchedBlockedReason.parse_dict(raw_ftrace_entry['function_args'], id) + + if not sbr: + print("WARNING: Failed to parse sched_blocked_reason: " + l) + else: + pending_sched_blocked_reasons.append(sbr) + + elif raw_ftrace_entry['function'] == 'mm_filemap_add_to_page_cache': + d = MmFilemapAddToPageCache.parse_dict(raw_ftrace_entry['function_args'], + id) + if not d: + print("WARNING: Failed to parse mm_filemap_add_to_page_cache: " + l) + else: + pending_mm_filemap_add_to_pagecaches.append(d) + + # Objects are cached in python memory, not yet sent to SQL database. + + # Send INSERT/UPDATE/etc statements to the underlying SQL database. + if count % _FLUSH_LIMIT == 0: + insert_all_pending_entries() + + insert_all_pending_entries() + + # Ensure underlying database commits changes from memory to disk. + session.commit() + + return count diff --git a/startop/scripts/trace_analyzer/lib/trace2db_test.py b/startop/scripts/trace_analyzer/lib/trace2db_test.py new file mode 100755 index 000000000000..3b326f000a7d --- /dev/null +++ b/startop/scripts/trace_analyzer/lib/trace2db_test.py @@ -0,0 +1,222 @@ +#!/usr/bin/env python3 +# +# Copyright 2019, The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +""" +Unit tests for inode2filename module. + +Install: + $> sudo apt-get install python3-pytest ## OR + $> pip install -U pytest +See also https://docs.pytest.org/en/latest/getting-started.html + +Usage: + $> ./inode2filename_test.py + $> pytest inode2filename_test.py + $> python -m pytest inode2filename_test.py + +See also https://docs.pytest.org/en/latest/usage.html +""" + +# global imports +import io +from copy import deepcopy + +# pip imports +# local imports +from trace2db import * + +# This pretty-prints the raw dictionary of the sqlalchemy object if it fails. +class EqualsSqlAlchemyObject: + # For convenience to write shorter tests, we also add 'ignore_fields' which allow us to specify + # which fields to ignore when doing the comparison. + def __init__(self_, self, ignore_fields=[]): + self_.self = self + self_.ignore_fields = ignore_fields + + # Do field-by-field comparison. + # It seems that SQLAlchemy does not implement __eq__ itself so we have to do it ourselves. + def __eq__(self_, other): + if isinstance(other, EqualsSqlAlchemyObject): + other = other.self + + self = self_.self + + classes_match = isinstance(other, self.__class__) + a, b = deepcopy(self.__dict__), deepcopy(other.__dict__) + + #compare based on equality our attributes, ignoring SQLAlchemy internal stuff + + a.pop('_sa_instance_state', None) + b.pop('_sa_instance_state', None) + + for f in self_.ignore_fields: + a.pop(f, None) + b.pop(f, None) + + attrs_match = (a == b) + return classes_match and attrs_match + + def __repr__(self): + return repr(self.self.__dict__) + + +def assert_eq_ignore_id(left, right): + # This pretty-prints the raw dictionary of the sqlalchemy object if it fails. + # It does field-by-field comparison, but ignores the 'id' field. + assert EqualsSqlAlchemyObject(left, ignore_fields=['id']) == EqualsSqlAlchemyObject(right) + +def parse_trace_file_to_db(*contents): + """ + Make temporary in-memory sqlite3 database by parsing the string contents as a trace. + + :return: Trace2Db instance + """ + buf = io.StringIO() + + for c in contents: + buf.write(c) + buf.write("\n") + + buf.seek(0) + + t2d = Trace2Db(":memory:") + t2d.parse_file_buf_into_db(buf) + + buf.close() + + return t2d + +def test_ftrace_mm_filemap_add_to_pagecache(): + test_contents = """ +MediaStoreImpor-27212 (27176) [000] .... 16136.595194: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=0000000060e990c7 pfn=677646 ofs=159744 +MediaStoreImpor-27212 (27176) [000] .... 16136.595920: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=0000000048e2e156 pfn=677645 ofs=126976 +MediaStoreImpor-27212 (27176) [000] .... 16136.597793: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=0000000051eabfb2 pfn=677644 ofs=122880 +MediaStoreImpor-27212 (27176) [000] .... 16136.597815: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=00000000ce7cd606 pfn=677643 ofs=131072 +MediaStoreImpor-27212 (27176) [000] .... 16136.603732: mm_filemap_add_to_page_cache: dev 253:6 ino 1 page=000000008ffd3030 pfn=730119 ofs=186482688 +MediaStoreImpor-27212 (27176) [000] .... 16136.604126: mm_filemap_add_to_page_cache: dev 253:6 ino b1d8 page=0000000098d4d2e2 pfn=829676 ofs=0 + <...>-27197 (-----) [002] .... 16136.613471: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=00000000aca88a97 pfn=743346 ofs=241664 + <...>-27197 (-----) [002] .... 16136.615979: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=00000000351f2bc1 pfn=777799 ofs=106496 + <...>-27224 (-----) [006] .... 16137.400090: mm_filemap_add_to_page_cache: dev 253:6 ino 712d page=000000006ff7ffdb pfn=754861 ofs=0 + <...>-1396 (-----) [000] .... 16137.451660: mm_filemap_add_to_page_cache: dev 253:6 ino 1 page=00000000ba0cbb34 pfn=769173 ofs=187191296 + <...>-1396 (-----) [000] .... 16137.453020: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=00000000f6ef038e pfn=820291 ofs=0 + <...>-1396 (-----) [000] .... 16137.453067: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=0000000083ebc446 pfn=956463 ofs=4096 + <...>-1396 (-----) [000] .... 16137.453101: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=000000009dc2cd25 pfn=822813 ofs=8192 + <...>-1396 (-----) [000] .... 16137.453113: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=00000000a11167fb pfn=928650 ofs=12288 + <...>-1396 (-----) [000] .... 16137.453126: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=00000000c1c3311b pfn=621110 ofs=16384 + <...>-1396 (-----) [000] .... 16137.453139: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=000000009aa78342 pfn=689370 ofs=20480 + <...>-1396 (-----) [000] .... 16137.453151: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=0000000082cddcd6 pfn=755584 ofs=24576 + <...>-1396 (-----) [000] .... 16137.453162: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=00000000b0249bc7 pfn=691431 ofs=28672 + <...>-1396 (-----) [000] .... 16137.453183: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=000000006a776ff0 pfn=795084 ofs=32768 + <...>-1396 (-----) [000] .... 16137.453203: mm_filemap_add_to_page_cache: dev 253:6 ino b285 page=000000001a4918a7 pfn=806998 ofs=36864 + <...>-2578 (-----) [002] .... 16137.561871: mm_filemap_add_to_page_cache: dev 253:6 ino 1 page=00000000d65af9d2 pfn=719246 ofs=187015168 + <...>-2578 (-----) [002] .... 16137.562846: mm_filemap_add_to_page_cache: dev 253:6 ino b25a page=000000002f6ba74f pfn=864982 ofs=0 + <...>-2578 (-----) [000] .... 16138.104500: mm_filemap_add_to_page_cache: dev 253:6 ino 1 page=00000000f888d0f6 pfn=805812 ofs=192794624 + <...>-2578 (-----) [000] .... 16138.105836: mm_filemap_add_to_page_cache: dev 253:6 ino b7dd page=000000003749523b pfn=977196 ofs=0 + <...>-27215 (-----) [001] .... 16138.256881: mm_filemap_add_to_page_cache: dev 253:6 ino 758f page=000000001b375de1 pfn=755928 ofs=0 + <...>-27215 (-----) [001] .... 16138.257526: mm_filemap_add_to_page_cache: dev 253:6 ino 7591 page=000000004e039481 pfn=841534 ofs=0 + NonUserFacing6-5246 ( 1322) [005] .... 16138.356491: mm_filemap_add_to_page_cache: dev 253:6 ino 1 page=00000000d65af9d2 pfn=719246 ofs=161890304 + NonUserFacing6-5246 ( 1322) [005] .... 16138.357538: mm_filemap_add_to_page_cache: dev 253:6 ino 9a64 page=000000002f6ba74f pfn=864982 ofs=0 + NonUserFacing6-5246 ( 1322) [005] .... 16138.357581: mm_filemap_add_to_page_cache: dev 253:6 ino 9a64 page=000000006e0f8322 pfn=797894 ofs=4096 + <...>-27197 (-----) [005] .... 16140.143224: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=00000000a42527c6 pfn=1076669 ofs=32768 + """ + + t2d = parse_trace_file_to_db(test_contents) + session = t2d.session + + first_row = session.query(MmFilemapAddToPageCache).order_by(MmFilemapAddToPageCache.id).first() + + #dev 253:6 ino 7580 page=0000000060e990c7 pfn=677646 ofs=159744 + assert_eq_ignore_id(MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0x7580, page=0x0000000060e990c7, pfn=677646, ofs=159744), first_row) + + second_to_last_row = session.query(MmFilemapAddToPageCache).filter(MmFilemapAddToPageCache.page.in_([0x000000006e0f8322])).first() + + # dev 253:6 ino 9a64 page=000000006e0f8322 pfn=797894 ofs=4096 + assert_eq_ignore_id(MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0x9a64, page=0x000000006e0f8322, pfn=797894, ofs=4096), second_to_last_row) + +def test_systrace_mm_filemap_add_to_pagecache(): + test_contents = """ +<!DOCTYPE html> +<html> +<head i18n-values="dir:textdirection;"> +<meta http-equiv="Content-Type" content="text/html; charset=utf-8"> +<meta charset="utf-8"/> +<title>Android System Trace</title> + <script class="trace-data" type="application/text"> +PROCESS DUMP +USER PID PPID VSZ RSS WCHAN PC S NAME COMM +root 1 0 62148 5976 0 0 S init [init] +root 2 0 0 0 0 0 S [kthreadd] [kthreadd] + </script> + + <script class="trace-data" type="application/text"> +MediaStoreImpor-27212 (27176) [000] .... 16136.595194: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=0000000060e990c7 pfn=677646 ofs=159744 +NonUserFacing6-5246 ( 1322) [005] .... 16138.357581: mm_filemap_add_to_page_cache: dev 253:6 ino 9a64 page=000000006e0f8322 pfn=797894 ofs=4096 + </script> + + <script class="trace-data" type="application/text"> +{"traceEvents": [{"category": "process_argv", "name": "process_argv", "args": {"argv": ["/mnt/ssd3/workspace/master/external/chromium-trace/systrace.py", "-t", "5", "pagecache"]}, "pid": 160383, "ts": 1037300940509.7991, "tid": 139628672526080, "ph": "M"}, {"category": "python", "name": "clock_sync", "args": {"issue_ts": 1037307346185.212, "sync_id": "9a7e4fe3-89ad-441f-8226-8fe533fe973e"}, "pid": 160383, "ts": 1037307351643.906, "tid": 139628726089536, "ph": "c"}], "metadata": {"clock-domain": "SYSTRACE"}} + </script> +<!-- END TRACE --> + """ + + t2d = parse_trace_file_to_db(test_contents) + session = t2d.session + + first_row = session.query(MmFilemapAddToPageCache).order_by(MmFilemapAddToPageCache.id).first() + + #dev 253:6 ino 7580 page=0000000060e990c7 pfn=677646 ofs=159744 + assert_eq_ignore_id(MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0x7580, page=0x0000000060e990c7, pfn=677646, ofs=159744), first_row) + + second_to_last_row = session.query(MmFilemapAddToPageCache).filter(MmFilemapAddToPageCache.page.in_([0x000000006e0f8322])).first() + + # dev 253:6 ino 9a64 page=000000006e0f8322 pfn=797894 ofs=4096 + assert_eq_ignore_id(MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0x9a64, page=0x000000006e0f8322, pfn=797894, ofs=4096), second_to_last_row) + +def test_timestamp_filter(): + test_contents = """ + MediaStoreImpor-27212 (27176) [000] .... 16136.595194: mm_filemap_add_to_page_cache: dev 253:6 ino 7580 page=0000000060e990c7 pfn=677646 ofs=159744 + NonUserFacing6-5246 ( 1322) [005] .... 16139.357581: mm_filemap_add_to_page_cache: dev 253:6 ino 9a64 page=000000006e0f8322 pfn=797894 ofs=4096 + MediaStoreImpor-27212 (27176) [000] .... 16136.604126: mm_filemap_add_to_page_cache: dev 253:6 ino b1d8 page=0000000098d4d2e2 pfn=829676 ofs=0 + """ + + t2d = parse_trace_file_to_db(test_contents) + session = t2d.session + + end_time = 16137.0 + + results = session.query(MmFilemapAddToPageCache).join( + MmFilemapAddToPageCache.raw_ftrace_entry).filter( + RawFtraceEntry.timestamp <= end_time).order_by( + MmFilemapAddToPageCache.id).all() + + assert len(results) == 2 + assert_eq_ignore_id( + MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0x7580, page=0x0000000060e990c7, pfn=677646, + ofs=159744), results[0]) + assert_eq_ignore_id( + MmFilemapAddToPageCache(dev=64774, dev_major=253, dev_minor=6, + ino=0xb1d8, page=0x0000000098d4d2e2, pfn=829676, + ofs=0), results[1]) + + +if __name__ == '__main__': + pytest.main() diff --git a/startop/scripts/trace_analyzer/queries_all.sql b/startop/scripts/trace_analyzer/queries_all.sql new file mode 100644 index 000000000000..41d1c0804a7f --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_all.sql @@ -0,0 +1,57 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +-- filter for atrace writes +CREATE VIEW IF NOT EXISTS tracing_mark_writes AS + SELECT * + FROM raw_ftrace_entries + WHERE function = 'tracing_mark_write'; + +-- split the tracing_mark_write function args by ||s +DROP TABLE IF exists tracing_mark_write_split_array; + +CREATE TABLE tracing_mark_write_split_array ( + predictorset_id INT REFERENCES raw_ftrace_entries (id), + predictor_name, + rest, + gen, + + UNIQUE(predictorset_id, gen) -- drops redundant inserts into table +); + +CREATE INDEX "tracing_mark_write_split_array_id" ON tracing_mark_write_split_array ( + predictorset_id COLLATE BINARY COLLATE BINARY +); + +INSERT INTO tracing_mark_write_split_array + WITH + split(predictorset_id, predictor_name, rest, gen) AS ( + -- split by | + SELECT id, '', function_args || '|', 0 FROM tracing_mark_writes WHERE id + UNION ALL + SELECT predictorset_id, + substr(rest, 0, instr(rest, '|')), + substr(rest, instr(rest, '|')+1), + gen + 1 + FROM split + WHERE rest <> ''), + split_results AS ( + SELECT * FROM split WHERE predictor_name <> '' + ) + SELECT * from split_results +; + + diff --git a/startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql b/startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql new file mode 100644 index 000000000000..c28475eec73d --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql @@ -0,0 +1,44 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +-- use the 'launching: $process_name' async slice to figure out launch duration. +DROP VIEW IF EXISTS launch_durations_named; + +CREATE VIEW launch_durations_named AS +WITH + launch_traces_raw AS ( + SELECT * + FROM tracing_mark_write_split AS tmw, + raw_ftrace_entries AS rfe + WHERE atrace_message LIKE 'launching: %' AND rfe.id = tmw.raw_ftrace_entry_id + ), + launch_traces_joined AS ( + SELECT started.timestamp AS started_timestamp, + finished.timestamp AS finished_timestamp, + started.id AS started_id, + finished.id AS finished_id, + SUBSTR(started.atrace_message, 12) AS proc_name -- crop out "launching: " from the string. + FROM launch_traces_raw AS started, + launch_traces_raw AS finished + -- async slices ('S' -> 'F') have matching counters given the same PID. + WHERE started.atrace_type == 'S' + AND finished.atrace_type == 'F' + AND started.atrace_count == finished.atrace_count + AND started.atrace_pid == finished.atrace_pid + ) +SELECT * from launch_traces_joined; + +SELECT * FROM launch_durations_named; diff --git a/startop/scripts/trace_analyzer/queries_block_launch.sql b/startop/scripts/trace_analyzer/queries_block_launch.sql new file mode 100644 index 000000000000..34e5f03d0c48 --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_block_launch.sql @@ -0,0 +1,52 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +DROP VIEW IF EXISTS blocked_iowait_for_app_launches; + +CREATE VIEW blocked_iowait_for_app_launches AS +WITH + block_launch_join AS ( + SELECT * + FROM blocking_durations AS bd, + launch_durations_named AS ld + WHERE bd.block_timestamp >= ld.started_timestamp + AND bd.unblock_timestamp <= ld.finished_timestamp + ), + blocked_ui_threads AS ( + SELECT * + FROM start_process_ui_threads AS sp, + block_launch_join AS blj + WHERE sp.atm_ui_thread_tid == unblock_pid + AND sp.process_name = blj.proc_name + ), + summed_raw AS ( + SELECT SUM(unblock_timestamp-block_timestamp)*1000 AS sum_block_duration_ms, + * + FROM blocked_ui_threads + GROUP BY unblock_pid + ), + summed_neat AS ( + SELECT sum_block_duration_ms AS blocked_iowait_duration_ms, + process_name, + (finished_timestamp - started_timestamp) * 1000 AS launching_duration_ms, + started_timestamp * 1000 AS launching_started_timestamp_ms, + finished_timestamp * 1000 AS launching_finished_timestamp_ms + -- filter out the rest because its just selecting 1 arbitrary row (due to the SUM aggregate)., + FROM summed_raw + ) +SELECT * FROM summed_neat; + +SELECT * FROM blocked_iowait_for_app_launches; diff --git a/startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql b/startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql new file mode 100644 index 000000000000..788d0dae47d3 --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql @@ -0,0 +1,101 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +DROP VIEW IF EXISTS sched_switch_iowaits_pre; + +-- scan for the closest pair such that: +-- sched_block_reason pid=$PID iowait=1 ... +-- ... +-- sched_switch next_pid=$PID +CREATE VIEW sched_switch_iowaits_pre AS + SELECT MAX(sbr.id) AS blocked_id, + ss.id AS sched_switch_id, + pid, -- iow.pid + iowait, -- iowait=0 or iowait=1 + caller, + sbr_f.timestamp AS blocked_timestamp, + ss_f.timestamp AS sched_switch_timestamp, + next_comm, -- name of next_pid + next_pid -- same as iow.pid + FROM sched_blocked_reasons AS sbr, + raw_ftrace_entries AS sbr_f, + sched_switches AS ss, + raw_ftrace_entries AS ss_f + WHERE sbr_f.id == sbr.id + AND ss_f.id == ss.id + AND sbr.pid == ss.next_pid + AND sbr.iowait = 1 + AND sbr_f.timestamp < ss_f.timestamp -- ensures the 'closest' sched_blocked_reason is selected. + GROUP BY ss.id +; + +DROP VIEW IF EXISTS sched_switch_iowaits; + +CREATE VIEW sched_switch_iowaits AS + SELECT *, MIN(sched_switch_timestamp) AS ss_timestamp -- drop all of the 'too large' sched_switch entries except the closest one. + FROM sched_switch_iowaits_pre + GROUP BY blocked_id; + +SELECT * FROM sched_switch_iowaits; + +-- use a real table here instead of a view, otherwise SQLiteStudio segfaults for some reason. +DROP TABLE IF EXISTS blocking_durations; + +CREATE TABLE blocking_durations AS +WITH + blocking_durations_raw AS ( + SELECT MAX(ss.id) AS block_id, + ssf.timestamp AS block_timestamp, + iow.sched_switch_timestamp AS unblock_timestamp, + ss.prev_comm as block_prev_comm, + iow.next_comm AS unblock_next_comm, + ss.prev_state AS block_prev_state, + iow.sched_switch_id AS unblock_id, + iow.pid AS unblock_pid, + iow.caller AS unblock_caller + FROM sched_switches AS ss, -- this is the sched_switch that caused a block (in the future when it unblocks, the reason is iowait=1). + sched_switch_iowaits AS iow, -- this is the sched_switch that removes the block (it is now running again). + raw_ftrace_entries AS ssf + WHERE ssf.id = ss.id AND ss.prev_pid == iow.next_pid AND ssf.timestamp < iow.sched_switch_timestamp + GROUP BY unblock_timestamp + ), + blocking_durations_tmp AS ( + SELECT block_id, + unblock_timestamp, + block_timestamp, + block_prev_comm as comm, + block_prev_state as block_state, + unblock_id, + unblock_pid, + unblock_caller + FROM blocking_durations_raw + ) + SELECT * FROM blocking_durations_tmp;-- ORDER BY block_id ASC; + --SELECT SUM(block_duration_ms) AS sum, * FROM blocking_durations GROUP BY unblock_pid ORDER BY sum DESC; + +DROP INDEX IF EXISTS "blocking_durations_block_timestamp"; + +CREATE INDEX "blocking_durations_block_timestamp" ON blocking_durations ( + block_timestamp COLLATE BINARY COLLATE BINARY +); + +DROP INDEX IF EXISTS "blocking_durations_unblock_timestamp"; + +CREATE INDEX "blocking_durations_unblock_timestamp" ON blocking_durations ( + unblock_timestamp COLLATE BINARY COLLATE BINARY +); + +SELECT * FROM blocking_durations; diff --git a/startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql b/startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql new file mode 100644 index 000000000000..0c166b09784c --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql @@ -0,0 +1,42 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +DROP VIEW IF EXISTS sched_switch_next_comm_pids; + +CREATE VIEW IF NOT EXISTS sched_switch_next_comm_pids AS + +-- TODO: switch to using sched_switches table. + +WITH + sched_switchs AS ( + SELECT * FROM raw_ftrace_entries WHERE function = 'sched_switch' AND function_args LIKE '% next_pid=%' AND function_args NOT LIKE '% next_comm=main %' + ), + comm_and_pids_raws AS ( + SELECT id, + SUBSTR(function_args, instr(function_args, "next_comm="), instr(function_args, "next_pid=") - instr(function_args, "next_comm=")) AS next_comm_raw, + SUBSTR(function_args, instr(function_args, "next_pid="), instr(function_args, "next_prio=") - instr(function_args, "next_pid=")) AS next_pid_raw + FROM sched_switchs + ), + comm_and_pids AS ( + SELECT id, + id AS raw_ftrace_entry_id, + TRIM(SUBSTR(next_pid_raw, 10)) AS next_pid, -- len("next_pid=") is 10 + TRIM(SUBSTR(next_comm_raw, 11)) AS next_comm -- len("next_comm=") is 11 + FROM comm_and_pids_raws + ) +SELECT * from comm_and_pids; + +SELECT * from sched_switch_next_comm_pids; diff --git a/startop/scripts/trace_analyzer/queries_get_procs.sql b/startop/scripts/trace_analyzer/queries_get_procs.sql new file mode 100644 index 000000000000..06871c6e16b6 --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_get_procs.sql @@ -0,0 +1,30 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +DROP VIEW IF EXISTS start_procs; + +CREATE VIEW IF NOT EXISTS start_procs AS +WITH + start_procs_raw AS ( + SELECT * from tracing_mark_write_split WHERE atrace_message LIKE 'Start proc: %' + ), + start_procs_substr AS ( + -- note: "12" is len("Start proc: ")+1. sqlite indices start at 1. + SELECT raw_ftrace_entry_id, atrace_pid, SUBSTR(atrace_message, 13) AS process_name FROM start_procs_raw + ) +SELECT * from start_procs_substr; + +SELECT * from start_procs; diff --git a/startop/scripts/trace_analyzer/queries_get_ui_threads.sql b/startop/scripts/trace_analyzer/queries_get_ui_threads.sql new file mode 100644 index 000000000000..876e50e9880a --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_get_ui_threads.sql @@ -0,0 +1,88 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +-- note: These queries do comparisons based on raw_ftrace_entries.id by treating it as if it was equivalent to the temporal timestamp. +-- in practice, the ID of raw_ftrace_entries is based on its order in the ftrace buffer [and on the same cpu its equivalent]. +-- we can always resort raw_ftrace_entries to ensure id order matches timestamp order. We should rarely need to compare by timestamp directly. +-- accessing 'floats' is inferior as they are harder to index, and will result in slower queries. +-- +-- Naming convention note: '_fid' corresponds to 'raw_ftrace_entry.id'. +DROP VIEW IF EXISTS start_process_ui_threads; + +-- Map of started process names to their UI thread's TID (as returned by gettid). +CREATE VIEW IF NOT EXISTS start_process_ui_threads AS +WITH + start_proc_tids AS ( + SELECT sp.raw_ftrace_entry_id AS start_proc_fid, + sp.atrace_pid AS atrace_pid, + sp.process_name AS process_name, + --MIN(nc.raw_ftrace_entry_id) as next_comm_fid, + nc.raw_ftrace_entry_id AS next_comm_fid, + nc.next_pid as next_pid, + nc.next_comm as next_comm, + SUBSTR(sp.process_name, -15) AS cut -- why -15? See TASK_MAX in kernel, the sched_switch name is truncated to 16 bytes. + FROM start_procs AS sp, + sched_switch_next_comm_pids AS nc + WHERE sp.process_name LIKE '%' || nc.next_comm -- kernel truncates the sched_switch::next_comm event, so we must match the prefix of the full name. + --WHERE SUBSTR(sp.process_name, -16) == nc.next_comm + --WHERE cut == nc.next_comm + ), + start_proc_tids_filtered AS ( + SELECT * + FROM start_proc_tids + WHERE next_comm_fid > start_proc_fid -- safeguard that avoids choosing "earlier" sched_switch before process was even started. + --ORDER BY start_proc_fid, next_comm_fid + ), + start_proc_all_threads AS ( + SELECT DISTINCT + start_proc_fid, -- this is the ftrace entry of the system server 'Start proc: $process_name'. only need this to join for timestamp. + process_name, -- this is the '$process_name' from the system server entry. + -- next up we have all the possible thread IDs as parsed from sched_switch that corresponds most closest to the start proc. + next_pid AS ui_thread_tpid, -- sched_switch.next_pid. This can be any of the threads in that process, it's not necessarily the main UI thread yet. + next_comm, + MIN(next_comm_fid) AS next_comm_fid -- don't pick the 'later' next_comm_fid because it could correspond to another app start. + FROM start_proc_tids_filtered + GROUP BY start_proc_fid, ui_thread_tpid + ), + activity_thread_mains AS ( + SELECT * FROM tracing_mark_write_split WHERE atrace_message = 'ActivityThreadMain' + ), + start_proc_ui_threads AS ( + SELECT start_proc_fid, + process_name, + ui_thread_tpid, + next_comm, + next_comm_fid, + atm.raw_ftrace_entry_id as atm_fid, + atm.atrace_pid as atm_ui_thread_tid + FROM start_proc_all_threads AS spt, + activity_thread_mains AS atm + WHERE atm.atrace_pid == spt.ui_thread_tpid AND atm.raw_ftrace_entry_id > spt.start_proc_fid -- Ensure we ignore earlier ActivityThreadMains prior to their Start proc. + ), + start_proc_ui_threads_filtered AS ( + SELECT start_proc_fid, + process_name, -- e.g. 'com.android.settings' + --ui_thread_tpid, + --next_comm, + --next_comm_fid, + MIN(atm_fid) AS atm_fid, + atm_ui_thread_tid -- equivalent to gettid() for the process's UI thread. + FROM start_proc_ui_threads + GROUP BY start_proc_fid, atm_ui_thread_tid -- find the temporally closest ActivityTaskMain to a "Start proc: $process_name" + ) +SELECT * FROM start_proc_ui_threads_filtered; + +SELECT * FROM start_process_ui_threads; diff --git a/startop/scripts/trace_analyzer/queries_mark_write_join.sql b/startop/scripts/trace_analyzer/queries_mark_write_join.sql new file mode 100644 index 000000000000..100f07403423 --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_mark_write_join.sql @@ -0,0 +1,53 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +DROP TABLE IF EXISTS tracing_mark_write_split; + +CREATE TABLE tracing_mark_write_split ( + raw_ftrace_entry_id INT REFERENCES raw_ftrace_entries (id), + atrace_type CHAR(1), -- only null for the first 2 sync timers. usually 'B', 'C', E', ... + atrace_pid INT, -- only null for first 2 sync timers + atrace_message, -- usually null for type='E' etc. + atrace_count, -- usually non-null only for 'C' + + UNIQUE(raw_ftrace_entry_id) -- drops redundant inserts into table +); + +INSERT INTO tracing_mark_write_split +WITH + pivoted AS ( + SELECT tx.predictorset_id, + --ty.predictorset_id, + --tz.predictorset_id, + --tzz.predictorset_id, + tx.predictor_name AS atrace_type, + CAST(ty.predictor_name AS integer) AS atrace_pid, + tz.predictor_name AS atrace_message, + CAST(tzz.predictor_name AS integer) AS atrace_count + FROM (SELECT * from tracing_mark_write_split_array WHERE gen = 1) AS tx + LEFT JOIN + (SELECT * FROM tracing_mark_write_split_array WHERE gen = 2) AS ty + ON tx.predictorset_id = ty.predictorset_id + LEFT JOIN + (SELECT * FROM tracing_mark_write_split_array WHERE gen = 3) AS tz + ON tx.predictorset_id = tz.predictorset_id + LEFT JOIN + (SELECT * FROM tracing_mark_write_split_array WHERE gen = 4) AS tzz + ON tx.predictorset_id = tzz.predictorset_id + ) +SELECT * from pivoted ORDER BY predictorset_id;-- LIMIT 100; + +SELECT * FROM tracing_mark_write_split; diff --git a/startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql b/startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql new file mode 100644 index 000000000000..bf5e3ccb4ac7 --- /dev/null +++ b/startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql @@ -0,0 +1,28 @@ +/* + * Copyright (C) 2019 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +.headers on +.mode quote + +SELECT * FROM blocked_iowait_for_app_launches; + +/* +Output as CSV example: + +'blocked_iowait_duration_ms','process_name','launching_duration_ms','launching_started_timestamp_ms','launching_finished_timestamp_ms' +125.33199995596078224,'com.android.settings',1022.4840000009862706,17149896.822000000626,17150919.305999998003 + +*/ diff --git a/startop/scripts/trace_analyzer/run-sql-queries b/startop/scripts/trace_analyzer/run-sql-queries new file mode 100755 index 000000000000..61a0ad42a339 --- /dev/null +++ b/startop/scripts/trace_analyzer/run-sql-queries @@ -0,0 +1,79 @@ +#!/bin/bash +# Copyright (C) 2019 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +DIR="$( cd "$(dirname "$0")" ; pwd -P )" + +if [[ $# -lt 1 ]]; then + echo "Usage: $0 <db-file>" +fi + +DB_TARGET=$1 + +if ! [[ -f $DB_TARGET ]]; then + echo "ERROR: File '$DB_TARGET' does not exist." >&2 + exit 1 +fi + +exec_sql_file() { + local filename="$1" + if ! [[ -f $filename ]]; then + echo "ERROR: Can't exec SQL file, '$filename' does not exist." >&2 + return 1 + fi + + sqlite3 "$DB_TARGET" < "$DIR"/"$filename" +} + +exec_sql_file_quiet() { + exec_sql_file "$@" > /dev/null +} + +# Some views/tables need other views already created, so order does matter. +# x -> y , means x depends on y. + +# View: tracing_mark_writes +# Table: tracing_mark_write_split_array -> tracing_mark_writes +exec_sql_file_quiet "queries_all.sql" + +# Table: tracing_mark_write_split -> tracing_mark_write_split_array +exec_sql_file_quiet "queries_mark_write_join.sql" + +# View: start_procs -> tracing_mark_write_split +exec_sql_file_quiet "queries_get_procs.sql" + +# View: sched_switch_next_comm_pids +exec_sql_file_quiet "queries_get_comm_and_pids.sql" + +# View: start_process_ui_threads -> start_procs, sched_switch_next_comm_pids +exec_sql_file_quiet "queries_get_ui_threads.sql" + +# View: launch_durations_named -> tracing_mark_write_split +exec_sql_file_quiet "queries_app_launch_spans_with_name.sql" + +# View: sched_switch_iowaits_pre +# View: sched_switch_iowaits -> sched_switch_iowaits_pre +# Table: blocking_durations -> sched_switch_iowaits +exec_sql_file_quiet "queries_find_sched_switch_unblocked.sql" + +# View: blocked_iowait_for_app_launches -> launch_durations_named, blocking_durations +exec_sql_file_quiet "queries_block_launch.sql" + +##### +##### +##### + +# Final queries + +exec_sql_file "queries_pretty_print_block_launch.sql" diff --git a/startop/scripts/trace_analyzer/test_fixtures/common_systrace b/startop/scripts/trace_analyzer/test_fixtures/common_systrace new file mode 100644 index 000000000000..802cb5562593 --- /dev/null +++ b/startop/scripts/trace_analyzer/test_fixtures/common_systrace @@ -0,0 +1,518 @@ +# tracer: nop +# +# entries-in-buffer/entries-written: 411983/411983 #P:8 +# +# _-----=> irqs-off +# / _----=> need-resched +# | / _---=> hardirq/softirq +# || / _--=> preempt-depth +# ||| / delay +# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION +# | | | | |||| | | + <...>-14603 (-----) [000] ...1 14592.893157: tracing_mark_write: trace_event_clock_sync: parent_ts=14592.892578 + <...>-14603 (-----) [000] ...1 14592.893172: tracing_mark_write: trace_event_clock_sync: realtime_ts=1557129597951 + <...>-18150 (-----) [004] d..2 14594.182110: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=kworker/u16:16 next_pid=23269 next_prio=120 + kworker/u16:16-23269 (23269) [004] d.h3 14594.182228: sched_blocked_reason: pid=18150 iowait=0 caller=a6xx_oob_set+0x194/0x3dc + kworker/u16:16-23269 (23269) [004] d..2 14594.182248: sched_switch: prev_comm=kworker/u16:16 prev_pid=23269 prev_prio=120 prev_state=D ==> next_comm=kworker/u16:18 next_pid=18150 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.182312: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.182488: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + kworker/u16:16-23269 (23269) [005] d..2 14594.182610: sched_switch: prev_comm=kworker/u16:16 prev_pid=23269 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.182626: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.182755: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.182975: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.183209: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.183371: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.184286: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 + kworker/u16:16-23269 (23269) [005] d..2 14594.184495: sched_switch: prev_comm=kworker/u16:16 prev_pid=23269 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <...>-18150 (-----) [004] d..2 14594.184498: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 + ksoftirqd/4-47 ( 47) [004] d..2 14594.185678: sched_switch: prev_comm=ksoftirqd/4 prev_pid=47 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 + kworker/6:2-10610 (10610) [006] d..2 14594.186012: sched_switch: prev_comm=kworker/6:2 prev_pid=10610 prev_prio=120 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-656 (-----) [001] .... 14594.219464: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-1803 (-----) [000] d..2 14594.219595: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-3359 (-----) [001] ...1 14594.219856: tracing_mark_write: S|1368|launching: com.google.android.dialer|0 + <...>-3359 (-----) [001] ...1 14594.219863: tracing_mark_write: B|1368|MetricsLogger:launchObserverNotifyActivityLaunched + <...>-3359 (-----) [001] ...1 14594.219869: tracing_mark_write: B|1368|MetricsLogger:convertActivityRecordToProto + <...>-1398 (-----) [006] ...1 14594.220160: tracing_mark_write: B|1368|updateInputWindows + <...>-3359 (-----) [001] .... 14594.220230: binder_set_priority: proc=1368 thread=3359 old=110 => new=120 desired=120 + <...>-1398 (-----) [006] ...1 14594.220588: tracing_mark_write: B|1368|android.os.Handler: com.android.server.wm.AppWindowToken$1 + <...>-1398 (-----) [006] ...1 14594.220722: tracing_mark_write: B|1368|ResourcesManager#getResources + <...>-1052 (-----) [002] d..2 14594.220884: sched_switch: prev_comm=statsd.writer prev_pid=1052 prev_prio=120 prev_state=S ==> next_comm=UiThreadHelper next_pid=2045 next_prio=118 + <...>-1398 (-----) [006] ...1 14594.220926: tracing_mark_write: B|1368|Theme::ApplyStyle + <...>-1398 (-----) [006] ...1 14594.220929: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-2007 (-----) [007] ...1 14594.220996: tracing_mark_write: B|2007|Choreographer#doFrame + <...>-2007 (-----) [007] ...1 14594.221005: tracing_mark_write: B|2007|animation + <...>-1398 (-----) [006] ...1 14594.221015: tracing_mark_write: B|1368|ResourcesManager#getResources + <...>-2045 (-----) [002] ...2 14594.221035: binder_set_priority: proc=1368 thread=1903 old=120 => new=118 desired=118 + <...>-2045 (-----) [002] d..2 14594.221065: sched_switch: prev_comm=UiThreadHelper prev_pid=2045 prev_prio=118 prev_state=S ==> next_comm=Binder:1368_4 next_pid=1903 next_prio=118 + <...>-1398 (-----) [006] ...1 14594.221080: tracing_mark_write: B|1368|AssetManager::SetApkAssets + <...>-2007 (-----) [007] ...1 14594.221110: tracing_mark_write: B|2007|traversal + <...>-656 (-----) [000] ...1 14594.221137: tracing_mark_write: B|625|requestNextVsync + <...>-656 (-----) [000] ...1 14594.221141: tracing_mark_write: B|625|resetIdleTimer + <...>-2007 (-----) [007] ...1 14594.221146: tracing_mark_write: B|2007|draw + <...>-2007 (-----) [007] ...1 14594.221160: tracing_mark_write: B|2007|Record View#draw() + <...>-660 (-----) [005] d..2 14594.221285: sched_switch: prev_comm=app prev_pid=660 prev_prio=97 prev_state=S ==> next_comm=RenderThread next_pid=2738 next_prio=110 + <...>-658 (-----) [004] d..2 14594.221327: sched_switch: prev_comm=DispSync prev_pid=658 prev_prio=97 prev_state=S ==> next_comm=android.display next_pid=1397 next_prio=117 + <...>-2738 (-----) [005] ...1 14594.221342: tracing_mark_write: B|2007|notifyFramePending + <...>-2738 (-----) [005] ...1 14594.221362: tracing_mark_write: B|2007|DrawFrame + <...>-2738 (-----) [005] ...1 14594.221369: tracing_mark_write: B|2007|query + <...>-2007 (-----) [007] d..2 14594.221369: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=110 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-1903 (-----) [002] .... 14594.221397: binder_set_priority: proc=1368 thread=1903 old=118 => new=120 desired=120 + <...>-2738 (-----) [005] ...2 14594.221400: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-2738 (-----) [005] d..2 14594.221430: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-1368 (-----) [003] ...1 14594.221431: tracing_mark_write: B|1368|Lock contention on GC thread flip lock (owner tid: 0) + <...>-656 (-----) [005] ...1 14594.221460: tracing_mark_write: B|625|query + <...>-656 (-----) [005] .... 14594.221528: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-2738 (-----) [007] ...1 14594.221552: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...2 14594.221563: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-2738 (-----) [007] d..2 14594.221600: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-1368 (-----) [003] d..2 14594.221623: sched_switch: prev_comm=system_server prev_pid=1368 prev_prio=118 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 + <...>-656 (-----) [007] ...1 14594.221628: tracing_mark_write: B|625|query + <...>-23031 (-----) [001] d..2 14594.221643: sched_switch: prev_comm=UiAutomation prev_pid=23031 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-2738 (-----) [007] ...1 14594.221664: tracing_mark_write: B|2007|syncFrameState + <...>-2738 (-----) [007] ...1 14594.221697: tracing_mark_write: B|2007|prepareTree + <...>-23008 (-----) [005] d..2 14594.221706: sched_switch: prev_comm=hub.uiautomator prev_pid=23008 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <...>-656 (-----) [000] .... 14594.221737: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-1803 (-----) [003] d..2 14594.221747: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 + <...>-1397 (-----) [004] d..2 14594.221806: sched_switch: prev_comm=android.display prev_pid=1397 prev_prio=117 prev_state=S ==> next_comm=Binder:2007_A next_pid=4180 next_prio=120 + <...>-1398 (-----) [006] d..2 14594.221816: sched_switch: prev_comm=android.anim prev_pid=1398 prev_prio=110 prev_state=R ==> next_comm=s.nexuslauncher next_pid=2007 next_prio=110 + <...>-2738 (-----) [007] ...1 14594.221824: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221830: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221834: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221841: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221843: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221846: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.221850: tracing_mark_write: B|2007|dequeueBuffer + <...>-2738 (-----) [007] ...2 14594.221864: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-2738 (-----) [007] d..2 14594.221985: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=crtc_event:97 next_pid=303 next_prio=83 + <...>-2007 (-----) [006] ...1 14594.221989: tracing_mark_write: B|2007|topResumedActivityChangeItem + <...>-303 (-----) [007] d..2 14594.222016: sched_switch: prev_comm=crtc_event:97 prev_pid=303 prev_prio=83 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120 + rcu_preempt-7 ( 7) [007] d..2 14594.222035: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=RenderThread next_pid=2738 next_prio=110 + migration/4-46 ( 46) [004] d..2 14594.222037: sched_switch: prev_comm=migration/4 prev_pid=46 prev_prio=0 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-2738 (-----) [007] d..2 14594.222039: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=kworker/u16:18 next_pid=18150 next_prio=120 + <...>-656 (-----) [004] ...1 14594.222100: tracing_mark_write: B|625|dequeueBuffer + <...>-656 (-----) [004] ...1 14594.222114: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 2 + <...>-2007 (-----) [006] ...2 14594.222131: binder_set_priority: proc=1368 thread=1903 old=120 => new=110 desired=110 + <...>-2007 (-----) [006] d..2 14594.222143: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=110 prev_state=S ==> next_comm=UiThreadHelper next_pid=2045 next_prio=118 + <...>-2613 (-----) [001] d..2 14594.222158: sched_switch: prev_comm=ogle.android.as prev_pid=2613 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-18150 (-----) [007] d..2 14594.222193: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-656 (-----) [004] .... 14594.222220: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-2738 (-----) [007] ...1 14594.222267: tracing_mark_write: B|2007|HWC release fence 36027 has signaled + <...>-656 (-----) [007] ...1 14594.223842: tracing_mark_write: B|625|queueBuffer + <...>-656 (-----) [007] ...1 14594.223845: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 2 + <...>-656 (-----) [007] ...1 14594.223871: tracing_mark_write: B|625|requestNextVsync + <...>-656 (-----) [007] ...1 14594.223873: tracing_mark_write: B|625|resetIdleTimer + <...>-656 (-----) [007] ...1 14594.223881: tracing_mark_write: B|625|addAndGetFrameTimestamps + <...>-1395 (-----) [001] d..2 14594.223909: sched_switch: prev_comm=android.ui prev_pid=1395 prev_prio=118 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-2738 (-----) [007] ...1 14594.223959: tracing_mark_write: B|2007|Trace GPU completion fence 36027 + <...>-11799 (-----) [006] ...1 14594.224006: tracing_mark_write: B|2007|waiting for GPU completion 36027 + <...>-11799 (-----) [006] ...1 14594.224009: tracing_mark_write: B|2007|waitForever + <...>-2613 (-----) [004] d..2 14594.224014: sched_switch: prev_comm=ogle.android.as prev_pid=2613 prev_prio=120 prev_state=S ==> next_comm=Binder:1803_6 next_pid=2173 next_prio=120 + <...>-11799 (-----) [006] d..1 14594.224014: fence_enable_signal: driver=kgsl-timeline timeline=kgsl-3d0_13-s.nexuslauncher(200 context=27 seqno=78002 + <...>-11799 (-----) [006] d..2 14594.224021: sched_switch: prev_comm=GPU completion prev_pid=11799 prev_prio=110 prev_state=S ==> next_comm=rcuop/6 next_pid=68 next_prio=120 + rcuop/6-68 ( 68) [006] d..2 14594.224044: sched_switch: prev_comm=rcuop/6 prev_pid=68 prev_prio=120 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-259 (-----) [006] d..2 14594.224132: sched_switch: prev_comm=kgsl_worker_thr prev_pid=259 prev_prio=97 prev_state=S ==> next_comm=Binder:2007_A next_pid=4180 next_prio=120 + <...>-3206 (-----) [001] d..2 14594.224167: sched_switch: prev_comm=aiai-vc-0 prev_pid=3206 prev_prio=139 prev_state=R ==> next_comm=ndroid.systemui next_pid=1803 next_prio=120 + lowpool[847]-14589 ( 2446) [005] d..1 14594.224300: mm_filemap_delete_from_page_cache: dev 0:1 ino 3d0034 page=000000008247d586 pfn=676904 ofs=0 + <...>-1803 (-----) [001] d..2 14594.224302: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=aiai-vc-0 next_pid=3206 next_prio=139 + <...>-3206 (-----) [001] d..2 14594.224433: sched_switch: prev_comm=aiai-vc-0 prev_pid=3206 prev_prio=139 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-1903 (-----) [003] ...1 14594.224490: tracing_mark_write: B|1368|dispatchingStartProcess:com.google.android.dialer + <...>-1903 (-----) [003] ...1 14594.224659: tracing_mark_write: B|1368|wmLayout + <...>-1903 (-----) [003] ...1 14594.224666: tracing_mark_write: B|1368|performSurfacePlacement + <...>-1903 (-----) [003] ...1 14594.224683: tracing_mark_write: B|1368|applySurfaceChanges + <...>-1903 (-----) [003] ...1 14594.224688: tracing_mark_write: B|1368|openSurfaceTransaction + <...>-2738 (-----) [007] ...1 14594.224711: tracing_mark_write: B|2007|query + <...>-1903 (-----) [003] ...1 14594.224714: tracing_mark_write: B|1368|performLayout + <...>-2738 (-----) [007] ...1 14594.224714: tracing_mark_write: B|2007|query + <...>-1903 (-----) [003] ...1 14594.224723: tracing_mark_write: B|1368|applyPostLayoutPolicy + <...>-2738 (-----) [007] d..2 14594.224752: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-656 (-----) [007] .... 14594.224766: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-1398 (-----) [002] ...1 14594.224801: tracing_mark_write: B|1368|Theme::ApplyStyle + <...>-1398 (-----) [002] ...1 14594.224805: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224820: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224826: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224833: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224838: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224846: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224853: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224859: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-1398 (-----) [002] ...1 14594.224864: tracing_mark_write: B|1368|AssetManager::GetBag + <...>-18150 (-----) [006] d..2 14594.228407: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=R+ ==> next_comm=mmc-cmdqd/0 next_pid=440 next_prio=98 + <...>-2738 (-----) [007] d..2 14594.228411: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=kworker/7:0H next_pid=76 next_prio=100 + <...>-1409 (-----) [004] ...1 14594.228417: tracing_mark_write: B|1368|Start proc: com.google.android.dialer + <...>-440 (-----) [006] d..2 14594.228418: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=kworker/u16:18 next_pid=18150 next_prio=120 + <...>-76 (-----) [007] d..2 14594.228430: sched_switch: prev_comm=kworker/7:0H prev_pid=76 prev_prio=100 prev_state=R+ ==> next_comm=mmc-cmdqd/0 next_pid=440 next_prio=98 + <...>-440 (-----) [007] d..2 14594.228434: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=kworker/7:0H next_pid=76 next_prio=100 + <...>-18150 (-----) [006] d..3 14594.228442: sched_blocked_reason: pid=1398 iowait=1 caller=wait_on_page_bit_common+0x2a8/0x5f8 + <...>-76 (-----) [007] d..2 14594.228442: sched_switch: prev_comm=kworker/7:0H prev_pid=76 prev_prio=100 prev_state=S ==> next_comm=RenderThread next_pid=2738 next_prio=110 + <...>-2738 (-----) [007] ...2 14594.228446: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-18150 (-----) [006] d..2 14594.228447: sched_switch: prev_comm=kworker/u16:18 prev_pid=18150 prev_prio=120 prev_state=R+ ==> next_comm=android.anim next_pid=1398 next_prio=110 + <...>-2738 (-----) [007] d..2 14594.228479: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-1409 (-----) [004] d..2 14594.228499: sched_switch: prev_comm=ActivityManager prev_pid=1409 prev_prio=118 prev_state=D ==> next_comm=Binder:965_2 next_pid=1041 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229271: tracing_mark_write: B|625|handleTransaction + <...>-1773 (-----) [004] .... 14594.229285: binder_set_priority: proc=625 thread=1773 old=110 => new=120 desired=120 + <...>-440 (-----) [007] d..2 14594.229301: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=RenderThread next_pid=2738 next_prio=110 + <...>-2738 (-----) [007] ...1 14594.229318: tracing_mark_write: B|2007|HWC release fence 36028 has signaled + <...>-2738 (-----) [007] ...1 14594.229331: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.229337: tracing_mark_write: B|2007|eglBeginFrame + <...>-2738 (-----) [007] ...1 14594.229352: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...1 14594.229354: tracing_mark_write: B|2007|query + <...>-791 (-----) [000] d..2 14594.229357: sched_switch: prev_comm=main prev_pid=791 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229440: tracing_mark_write: B|625|doTransaction + <...>-13916 (-----) [002] d..2 14594.229482: sched_switch: prev_comm=HeapTaskDaemon prev_pid=13916 prev_prio=124 prev_state=D|K ==> next_comm=swapper/2 next_pid=0 next_prio=120 + <...>-13917 (-----) [001] d..2 14594.229492: sched_blocked_reason: pid=13916 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-625 (-----) [003] ...1 14594.229492: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229507: tracing_mark_write: B|625|doTransaction + <...>-13917 (-----) [001] d..2 14594.229523: sched_switch: prev_comm=ReferenceQueueD prev_pid=13917 prev_prio=124 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-13916 (-----) [002] d..2 14594.229535: sched_blocked_reason: pid=13917 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-625 (-----) [003] ...1 14594.229538: tracing_mark_write: B|625|doTransaction + <...>-2738 (-----) [007] ...1 14594.229543: tracing_mark_write: B|2007|flush commands + <...>-13916 (-----) [002] .... 14594.229562: sched_process_exit: comm=HeapTaskDaemon pid=13916 prio=124 + <...>-625 (-----) [003] ...1 14594.229567: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229588: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229628: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229652: tracing_mark_write: B|625|doTransaction + <...>-13916 (-----) [002] d..2 14594.229676: sched_switch: prev_comm=HeapTaskDaemon prev_pid=13916 prev_prio=124 prev_state=x ==> next_comm=swapper/2 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229676: tracing_mark_write: B|625|doTransaction + <...>-2007 (-----) [006] d..2 14594.229688: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=110 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229703: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229725: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229750: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229772: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.229792: tracing_mark_write: B|625|doTransaction + <...>-791 (-----) [000] d..2 14594.229811: sched_switch: prev_comm=main prev_pid=791 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229824: tracing_mark_write: B|625|doTransaction + <...>-2738 (-----) [007] ...1 14594.229827: tracing_mark_write: B|2007|eglSwapBuffersWithDamageKHR + <...>-13917 (-----) [001] d..2 14594.229836: sched_switch: prev_comm=ReferenceQueueD prev_pid=13917 prev_prio=124 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-2738 (-----) [007] ...1 14594.229837: tracing_mark_write: B|2007|setSurfaceDamage + <...>-625 (-----) [003] ...1 14594.229850: tracing_mark_write: B|625|doTransaction + <...>-13918 (-----) [002] d..2 14594.229856: sched_blocked_reason: pid=13917 iowait=0 caller=SyS_madvise+0xd34/0xd3c + <...>-5281 (-----) [001] d..2 14594.229932: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-89 (-----) [006] d..2 14594.229951: sched_switch: prev_comm=lpass_smem_glin prev_pid=89 prev_prio=98 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.229982: tracing_mark_write: B|625|handleMessageInvalidate + <...>-625 (-----) [003] ...1 14594.229984: tracing_mark_write: B|625|handlePageFlip + <...>-625 (-----) [003] ...1 14594.230013: tracing_mark_write: B|625|latchBuffer + <...>-13917 (-----) [000] .... 14594.230015: sched_process_exit: comm=ReferenceQueueD pid=13917 prio=124 + <...>-625 (-----) [003] ...1 14594.230020: tracing_mark_write: B|625|query + <...>-625 (-----) [003] ...1 14594.230028: tracing_mark_write: B|625|updateTexImage + <...>-625 (-----) [003] ...1 14594.230035: tracing_mark_write: B|625|acquireBuffer + <...>-625 (-----) [003] ...1 14594.230044: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 2 + <...>-2738 (-----) [007] d..2 14594.230057: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=D ==> next_comm=smem_native_lpa next_pid=88 next_prio=120 + <...>-14607 (-----) [000] d..2 14594.259609: sched_blocked_reason: pid=14624 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-2738 (-----) [005] d..2 14594.259620: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=120 prev_state=S ==> next_comm=Binder:625_4 next_pid=1773 next_prio=120 + <...>-1773 (-----) [005] ...1 14594.259649: tracing_mark_write: B|625|query + <...>-2738 (-----) [005] ...1 14594.259714: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] d..2 14594.259743: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=120 prev_state=S ==> next_comm=Binder:625_4 next_pid=1773 next_prio=120 + <...>-1773 (-----) [005] ...1 14594.259757: tracing_mark_write: B|625|query + <...>-2738 (-----) [005] ...1 14594.259810: tracing_mark_write: B|2007|syncFrameState + <...>-2738 (-----) [005] ...1 14594.259856: tracing_mark_write: B|2007|prepareTree + Binder:14607_1-14624 (14607) [002] ...1 14594.259863: tracing_mark_write: B|14607|AttachCurrentThread + Binder:14607_1-14624 (14607) [002] ...1 14594.259869: tracing_mark_write: B|14607|Thread::Attach + Binder:14607_1-14624 (14607) [002] ...1 14594.259873: tracing_mark_write: B|14607|Thread birth + Binder:14607_1-14624 (14607) [002] ...1 14594.259916: tracing_mark_write: B|14607|Thread::Init + Binder:14607_1-14624 (14607) [002] ...1 14594.259920: tracing_mark_write: B|14607|InitStackHwm + <...>-14607 (-----) [000] d..2 14594.259932: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_1-14624 (14607) [002] d..2 14594.259941: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-3198 (-----) [001] ...1 14594.259942: tracing_mark_write: B|2007|Update SurfaceView position + Binder:14607_1-14624 (14607) [002] ...1 14594.259963: tracing_mark_write: B|14607|InitTlsEntryPoints + Binder:14607_1-14624 (14607) [002] ...1 14594.259974: tracing_mark_write: B|14607|InitInterpreterTls + <...>-14607 (-----) [000] d..2 14594.260005: sched_blocked_reason: pid=14624 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-3198 (-----) [001] d..2 14594.260007: sched_switch: prev_comm=hwuiTask1 prev_pid=3198 prev_prio=118 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-14607 (-----) [000] d..2 14594.260024: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_1-14624 (14607) [002] d..2 14594.260038: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260064: sched_blocked_reason: pid=14624 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + Binder:14607_1-14624 (14607) [002] ...1 14594.260101: tracing_mark_write: B|14607|ThreadList::Register + <...>-2738 (-----) [005] ...1 14594.260128: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260140: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260148: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260155: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260161: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260167: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260173: tracing_mark_write: B|2007|dequeueBuffer + <...>-2007 (-----) [001] d..2 14594.260201: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-2738 (-----) [005] d..2 14594.260214: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=120 prev_state=S ==> next_comm=Binder:625_4 next_pid=1773 next_prio=120 + <...>-1773 (-----) [005] ...1 14594.260236: tracing_mark_write: B|625|dequeueBuffer + <...>-1773 (-----) [005] ...1 14594.260249: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 2 + <...>-14607 (-----) [000] d..2 14594.260334: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_1-14624 (14607) [002] d..2 14594.260343: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260376: sched_blocked_reason: pid=14624 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] d..2 14594.260387: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-2738 (-----) [005] ...1 14594.260401: tracing_mark_write: B|2007|HWC release fence 36030 has signaled + Binder:14607_1-14624 (14607) [002] d..2 14594.260407: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-2738 (-----) [005] ...1 14594.260419: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260427: tracing_mark_write: B|2007|eglBeginFrame + <...>-2738 (-----) [005] ...1 14594.260445: tracing_mark_write: B|2007|query + <...>-2738 (-----) [005] ...1 14594.260450: tracing_mark_write: B|2007|query + Binder:14607_1-14624 (14607) [002] .... 14594.260472: task_newtask: pid=14625 comm=Binder:14607_1 clone_flags=3d0f00 oom_score_adj=-1000 + <...>-14607 (-----) [000] d..2 14594.260517: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260525: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260555: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] ...1 14594.260569: tracing_mark_write: B|14607|ActivityThreadMain + <...>-14607 (-----) [000] d..2 14594.260581: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260588: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260611: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] d..2 14594.260623: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260636: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260663: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] d..2 14594.260674: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260694: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.260724: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-2738 (-----) [005] ...1 14594.260734: tracing_mark_write: B|2007|flush commands + <...>-14607 (-----) [000] d..2 14594.260735: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260753: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + Binder:14607_2-14625 (14607) [001] ...1 14594.260925: tracing_mark_write: B|14607|AttachCurrentThread + Binder:14607_2-14625 (14607) [001] ...1 14594.260930: tracing_mark_write: B|14607|Thread::Attach + Binder:14607_2-14625 (14607) [001] ...1 14594.260933: tracing_mark_write: B|14607|Thread birth + Binder:14607_2-14625 (14607) [001] ...1 14594.260973: tracing_mark_write: B|14607|Thread::Init + Binder:14607_2-14625 (14607) [001] ...1 14594.260977: tracing_mark_write: B|14607|InitStackHwm + <...>-14607 (-----) [000] d..2 14594.260990: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.260998: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + Binder:14607_2-14625 (14607) [001] ...1 14594.261023: tracing_mark_write: B|14607|InitTlsEntryPoints + Binder:14607_2-14625 (14607) [001] ...1 14594.261034: tracing_mark_write: B|14607|InitInterpreterTls + <...>-14607 (-----) [000] d..2 14594.261064: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] d..2 14594.261075: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.261094: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] d..2 14594.261120: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-14607 (-----) [000] d..2 14594.261132: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + Binder:14607_2-14625 (14607) [001] d..2 14594.261146: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + Binder:14607_2-14625 (14607) [001] ...1 14594.261167: tracing_mark_write: B|14607|ThreadList::Register + <...>-14607 (-----) [000] d..2 14594.261209: sched_blocked_reason: pid=14625 iowait=0 caller=__rwsem_down_write_failed_common+0x3e8/0x754 + <...>-2738 (-----) [005] ...1 14594.261212: tracing_mark_write: B|2007|waitOnFences + <...>-14607 (-----) [000] d..2 14594.261220: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-2738 (-----) [005] ...1 14594.261232: tracing_mark_write: B|2007|eglSwapBuffersWithDamageKHR + <...>-2738 (-----) [005] ...1 14594.261244: tracing_mark_write: B|2007|setSurfaceDamage + Binder:14607_2-14625 (14607) [001] d..2 14594.261246: sched_blocked_reason: pid=14607 iowait=0 caller=do_page_fault+0x550/0x5fc + <...>-14607 (-----) [000] ...1 14594.261326: tracing_mark_write: B|14607|VerifyClass com.android.org.conscrypt.TrustedCertificateStore$PreloadHolder + <...>-2738 (-----) [005] .... 14594.261621: fence_init: driver=kgsl-timeline timeline=kgsl-3d0_13-s.nexuslauncher(200 context=27 seqno=78005 + <...>-625 (-----) [003] ...1 14594.263903: tracing_mark_write: B|625|resetIdleTimer + <...>-625 (-----) [003] ...1 14594.263912: tracing_mark_write: B|625|rebuildLayerStacks + <...>-625 (-----) [003] ...1 14594.263915: tracing_mark_write: B|625|rebuildLayerStacks VR Dirty + <...>-625 (-----) [003] ...1 14594.263919: tracing_mark_write: B|625|computeVisibleRegions + <...>-1398 (-----) [006] d..2 14594.263966: sched_switch: prev_comm=android.anim prev_pid=1398 prev_prio=110 prev_state=S ==> next_comm=Binder:625_4 next_pid=1773 next_prio=120 + <...>-1695 (-----) [001] d..2 14594.264086: sched_switch: prev_comm=InputDispatcher prev_pid=1695 prev_prio=112 prev_state=S ==> next_comm=Binder:1368_14 next_pid=3253 next_prio=120 + <...>-625 (-----) [003] ...1 14594.264293: tracing_mark_write: B|625|calculateWorkingSet + <...>-625 (-----) [003] ...1 14594.264500: tracing_mark_write: B|625|prepare + <...>-625 (-----) [003] ...1 14594.264513: tracing_mark_write: B|625|HIDL::IComposerClient::executeCommands_2_2::client + <...>-625 (-----) [003] ...2 14594.264584: binder_set_priority: proc=627 thread=627 old=97 => new=98 desired=98 + <...>-625 (-----) [003] d..2 14594.264617: sched_switch: prev_comm=surfaceflinger prev_pid=625 prev_prio=98 prev_state=S ==> next_comm=logd.writer next_pid=588 next_prio=130 + <...>-588 (-----) [003] d..2 14594.264851: sched_switch: prev_comm=logd.writer prev_pid=588 prev_prio=130 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 + rcu_preempt-7 ( 7) [007] d..2 14594.265273: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=kworker/u16:3 next_pid=18008 next_prio=120 + <...>-18008 (-----) [007] d..2 14594.265404: sched_switch: prev_comm=kworker/u16:3 prev_pid=18008 prev_prio=120 prev_state=D ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-18008 (-----) [007] d..2 14594.265471: sched_switch: prev_comm=kworker/u16:3 prev_pid=18008 prev_prio=120 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.265496: tracing_mark_write: B|625|doComposition + <...>-625 (-----) [003] ...1 14594.265507: tracing_mark_write: B|625|doComposeSurfaces + <...>-625 (-----) [003] ...1 14594.265552: tracing_mark_write: B|625|acquireBuffer + <...>-625 (-----) [003] ...1 14594.265563: tracing_mark_write: B|625|postFramebuffer + <...>-625 (-----) [003] ...1 14594.265567: tracing_mark_write: B|625|presentAndGetReleaseFences + <...>-625 (-----) [003] d..1 14594.265601: fence_enable_signal: driver=sde_fence:crtc97:91650 timeline=crtc97 context=3 seqno=91650 + <...>-625 (-----) [003] ...1 14594.265735: tracing_mark_write: B|625|logLayerStats + <...>-625 (-----) [003] ...1 14594.265744: tracing_mark_write: B|625|postComposition + <...>-625 (-----) [003] ...1 14594.265749: tracing_mark_write: B|625|releaseBuffer + <...>-625 (-----) [003] ...1 14594.265753: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 1 + <...>-625 (-----) [003] ...1 14594.265791: tracing_mark_write: B|625|releaseBuffer + <...>-440 (-----) [007] d..2 14594.342366: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=kworker/u17:2 next_pid=1778 next_prio=100 + <...>-2007 (-----) [006] ...1 14594.342375: tracing_mark_write: B|2007|input + <...>-2007 (-----) [006] ...1 14594.342399: tracing_mark_write: B|2007|animation + <...>-625 (-----) [003] ...1 14594.342447: tracing_mark_write: B|625|doTransaction + <...>-625 (-----) [003] ...1 14594.342489: tracing_mark_write: B|625|doTransaction + kworker/u17:2-1778 ( 1778) [007] d..3 14594.342532: sched_blocked_reason: pid=14607 iowait=1 caller=wait_on_page_bit_common+0x2a8/0x5f8 + kworker/u17:2-1778 ( 1778) [007] d..2 14594.342544: sched_switch: prev_comm=kworker/u17:2 prev_pid=1778 prev_prio=100 prev_state=S ==> next_comm=kworker/u16:2 next_pid=27544 next_prio=120 + <...>-1773 (-----) [000] ...1 14594.342575: tracing_mark_write: B|625|requestNextVsync + <...>-1773 (-----) [000] ...1 14594.342579: tracing_mark_write: B|625|resetIdleTimer + <...>-27544 (-----) [007] d..2 14594.342589: sched_switch: prev_comm=kworker/u16:2 prev_pid=27544 prev_prio=120 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-656 (-----) [002] d.h3 14594.342604: sched_blocked_reason: pid=1233 iowait=0 caller=geni_i2c_xfer+0x4d8/0x1398 + <...>-1803 (-----) [001] d..2 14594.342605: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.342632: tracing_mark_write: B|625|handleMessageInvalidate + <...>-625 (-----) [003] ...1 14594.342634: tracing_mark_write: B|625|handlePageFlip + <...>-2738 (-----) [007] ...1 14594.342641: tracing_mark_write: B|2007|notifyFramePending + <...>-658 (-----) [002] d..2 14594.342653: sched_switch: prev_comm=DispSync prev_pid=658 prev_prio=97 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=120 + <...>-656 (-----) [002] ...1 14594.342656: tracing_mark_write: B|625|requestNextVsync + <...>-2738 (-----) [007] d..2 14594.342658: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-656 (-----) [002] ...1 14594.342660: tracing_mark_write: B|625|resetIdleTimer + <...>-660 (-----) [005] d..2 14594.342663: sched_switch: prev_comm=app prev_pid=660 prev_prio=97 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.342665: tracing_mark_write: B|625|latchBuffer + <...>-625 (-----) [003] ...1 14594.342673: tracing_mark_write: B|625|query + <...>-625 (-----) [003] ...1 14594.342682: tracing_mark_write: B|625|updateTexImage + <...>-625 (-----) [003] ...1 14594.342693: tracing_mark_write: B|625|acquireBuffer + <...>-625 (-----) [003] ...1 14594.342703: tracing_mark_write: B|625|com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity#1: 1 + <...>-660 (-----) [005] d..2 14594.342709: sched_switch: prev_comm=app prev_pid=660 prev_prio=97 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <...>-2007 (-----) [006] ...1 14594.342733: tracing_mark_write: B|2007|traversal + <...>-2007 (-----) [006] ...1 14594.342776: tracing_mark_write: B|2007|draw + <...>-2007 (-----) [006] ...1 14594.342791: tracing_mark_write: B|2007|Record View#draw() + <...>-625 (-----) [003] ...1 14594.342849: tracing_mark_write: B|625|updateInputFlinger + <...>-2007 (-----) [006] d..2 14594.342903: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=110 prev_state=S ==> next_comm=kworker/6:2H next_pid=24261 next_prio=100 + <...>-2738 (-----) [007] ...1 14594.342910: tracing_mark_write: B|2007|DrawFrame + <...>-2738 (-----) [007] d..2 14594.342917: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=mmc-cmdqd/0 next_pid=440 next_prio=98 + <...>-24261 (-----) [006] d..2 14594.342918: sched_switch: prev_comm=kworker/6:2H prev_pid=24261 prev_prio=100 prev_state=S ==> next_comm=.android.dialer next_pid=14607 next_prio=110 + <...>-440 (-----) [007] d..2 14594.342926: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=RenderThread next_pid=2738 next_prio=110 + <...>-2738 (-----) [007] ...1 14594.342927: tracing_mark_write: B|2007|query + <...>-2738 (-----) [007] ...2 14594.342959: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-2738 (-----) [007] d..2 14594.342975: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-656 (-----) [007] ...1 14594.343021: tracing_mark_write: B|625|query + <...>-656 (-----) [007] .... 14594.343033: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-2738 (-----) [007] ...1 14594.343070: tracing_mark_write: B|2007|query + <...>-1233 (-----) [004] d..2 14594.343074: sched_switch: prev_comm=sound trigger c prev_pid=1233 prev_prio=120 prev_state=R+ ==> next_comm=irq/144-1436400 next_pid=2522 next_prio=49 + <...>-2738 (-----) [007] ...2 14594.343078: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-625 (-----) [003] ...1 14594.343084: tracing_mark_write: B|625|onMessageReceived + <...>-625 (-----) [003] ...1 14594.343087: tracing_mark_write: B|625|handleMessageRefresh + <...>-625 (-----) [003] ...1 14594.343090: tracing_mark_write: B|625|preComposition + <...>-2738 (-----) [007] d..2 14594.343090: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-625 (-----) [003] ...1 14594.343122: tracing_mark_write: B|625|rebuildLayerStacks + <...>-625 (-----) [003] ...1 14594.343124: tracing_mark_write: B|625|rebuildLayerStacks VR Dirty + <...>-89 (-----) [007] d..2 14594.343126: sched_switch: prev_comm=lpass_smem_glin prev_pid=89 prev_prio=98 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-625 (-----) [003] ...1 14594.343129: tracing_mark_write: B|625|computeVisibleRegions + <...>-656 (-----) [007] ...1 14594.343136: tracing_mark_write: B|625|query + <...>-14607 (-----) [006] ...2 14594.343141: binder_set_priority: proc=1368 thread=3253 old=120 => new=110 desired=110 + <...>-2965 (-----) [001] .... 14596.746610: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=000000002ae8fcff pfn=1522884 ofs=188416 + <idle>-0 (-----) [002] d..2 14596.746619: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=mmc-cmdqd/0 next_pid=440 next_prio=98 + <...>-2965 (-----) [001] .... 14596.746629: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000679ee1ec pfn=1299913 ofs=192512 + <...>-2965 (-----) [001] .... 14596.746664: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=0000000006cd2fb7 pfn=1296251 ofs=196608 + <...>-2965 (-----) [001] .... 14596.746677: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000af82f3d6 pfn=1419330 ofs=200704 + <...>-2965 (-----) [001] .... 14596.746693: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=000000002840f054 pfn=1304928 ofs=204800 + <...>-2965 (-----) [001] .... 14596.746706: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=000000004a59da17 pfn=1288069 ofs=208896 + <...>-2965 (-----) [001] .... 14596.746717: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=0000000023a80dca pfn=1419686 ofs=212992 + <...>-2965 (-----) [001] .... 14596.746730: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=000000001cf89eab pfn=1315372 ofs=217088 + <...>-2965 (-----) [001] .... 14596.746743: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=000000005b4c6cb6 pfn=1380698 ofs=221184 + <...>-2965 (-----) [001] .... 14596.746760: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000f8304ae7 pfn=1206753 ofs=225280 + <...>-2965 (-----) [001] .... 14596.746773: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000cb912305 pfn=1325465 ofs=229376 + <...>-2965 (-----) [001] .... 14596.746785: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000f16f3774 pfn=1408056 ofs=233472 + <...>-2965 (-----) [001] .... 14596.746801: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=0000000056d4c926 pfn=1418352 ofs=237568 + <...>-2965 (-----) [001] .... 14596.746815: mm_filemap_add_to_page_cache: dev 253:6 ino a359 page=00000000f3eeb42c pfn=1320957 ofs=241664 + <...>-440 (-----) [002] d..2 14596.746916: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=440 prev_prio=98 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120 + + <...>-656 (-----) [007] .... 14594.343145: binder_set_priority: proc=625 thread=656 old=110 => new=120 desired=120 + <...>-14607 (-----) [006] d..2 14594.343164: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=110 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-5281 (-----) [002] d..2 14594.343177: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=RenderThread next_pid=2738 next_prio=110 + irq/144-1436400-2522 ( 2522) [004] d..2 14594.343223: sched_switch: prev_comm=irq/144-1436400 prev_pid=2522 prev_prio=49 prev_state=D ==> next_comm=sound trigger c next_pid=1233 next_prio=120 + <...>-88 (-----) [006] d..2 14594.343240: sched_switch: prev_comm=smem_native_lpa prev_pid=88 prev_prio=98 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-1238 (-----) [001] d..2 14594.343243: sched_switch: prev_comm=FastMixer prev_pid=1238 prev_prio=96 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-2738 (-----) [002] ...1 14594.343244: tracing_mark_write: B|2007|syncFrameState + <...>-2738 (-----) [002] ...1 14594.343293: tracing_mark_write: B|2007|prepareTree + <...>-1695 (-----) [001] d..2 14594.343318: sched_switch: prev_comm=InputDispatcher prev_pid=1695 prev_prio=112 prev_state=R+ ==> next_comm=FastMixer next_pid=1238 next_prio=96 + <...>-5281 (-----) [005] d..2 14594.343322: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=Binder:1368_14 next_pid=3253 next_prio=110 + <...>-1238 (-----) [001] d..2 14594.343442: sched_switch: prev_comm=FastMixer prev_pid=1238 prev_prio=96 prev_state=S ==> next_comm=InputDispatcher next_pid=1695 next_prio=112 + <...>-1695 (-----) [001] d..2 14594.343467: sched_switch: prev_comm=InputDispatcher prev_pid=1695 prev_prio=112 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 + <...>-5281 (-----) [000] d..2 14594.343484: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 + <...>-625 (-----) [003] ...1 14594.343519: tracing_mark_write: B|625|calculateWorkingSet + <...>-2738 (-----) [002] ...1 14594.343568: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343577: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343586: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343591: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343597: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343602: tracing_mark_write: B|2007|query + <...>-2738 (-----) [002] ...1 14594.343609: tracing_mark_write: B|2007|dequeueBuffer + <...>-2007 (-----) [006] d..2 14594.343612: sched_switch: prev_comm=s.nexuslauncher prev_pid=2007 prev_prio=110 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120 + <...>-2738 (-----) [002] ...2 14594.343633: binder_set_priority: proc=625 thread=656 old=120 => new=110 desired=110 + <...>-2738 (-----) [002] d..2 14594.343683: sched_switch: prev_comm=RenderThread prev_pid=2738 prev_prio=110 prev_state=R+ ==> next_comm=Binder:625_1 next_pid=656 next_prio=110 + <...>-625 (-----) [003] ...1 14594.343704: tracing_mark_write: B|625|prepare + <...>-656 (-----) [002] ...1 14594.343707: tracing_mark_write: B|625|dequeueBuffer + <...>-625 (-----) [004] ...1 14594.812869: tracing_mark_write: B|625|com.google.android.dialer/com.google.android.dialer.extensions.GoogleDialtactsActivity#0: 2 + <...>-2048 (-----) [000] d..2 14594.812895: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=Binder:625_3 next_pid=1431 next_prio=120 + <...>-1431 (-----) [000] ...1 14594.812911: tracing_mark_write: B|625|query + <...>-625 (-----) [004] ...1 14594.812914: tracing_mark_write: B|625|latchBuffer + <...>-625 (-----) [004] ...1 14594.812919: tracing_mark_write: B|625|query + <...>-625 (-----) [004] ...1 14594.812925: tracing_mark_write: B|625|updateTexImage + <...>-625 (-----) [004] ...1 14594.812928: tracing_mark_write: B|625|acquireBuffer + <...>-625 (-----) [004] ...1 14594.812934: tracing_mark_write: B|625|StatusBar#0: 1 + <...>-2048 (-----) [000] ...1 14594.812962: tracing_mark_write: B|1803|syncFrameState + <...>-656 (-----) [002] ...1 14594.813044: tracing_mark_write: B|625|setTransactionState + <...>-14607 (-----) [007] ...2 14594.813083: binder_set_priority: proc=10691 thread=18733 old=120 => new=110 desired=110 + <...>-14607 (-----) [007] d..2 14594.813114: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=110 prev_state=S ==> next_comm=kworker/7:1 next_pid=7092 next_prio=120 + <...>-14655 (-----) [006] d..2 14594.813128: sched_switch: prev_comm=DialerExecutors prev_pid=14655 prev_prio=130 prev_state=R ==> next_comm=lpass_smem_glin next_pid=89 next_prio=98 + <...>-89 (-----) [006] d..2 14594.813163: sched_switch: prev_comm=lpass_smem_glin prev_pid=89 prev_prio=98 prev_state=S ==> next_comm=DialerExecutors next_pid=14655 next_prio=130 + <...>-656 (-----) [002] ...1 14594.813218: tracing_mark_write: B|625|requestNextVsync + <...>-656 (-----) [002] ...1 14594.813222: tracing_mark_write: B|625|resetIdleTimer + kworker/7:1-7092 ( 7092) [007] d..2 14594.813239: sched_switch: prev_comm=kworker/7:1 prev_pid=7092 prev_prio=120 prev_state=R+ ==> next_comm=smem_native_lpa next_pid=88 next_prio=98 + <...>-5281 (-----) [001] d..2 14594.813245: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=Binder:10691_B next_pid=18733 next_prio=110 + <...>-88 (-----) [007] d..2 14594.813248: sched_switch: prev_comm=smem_native_lpa prev_pid=88 prev_prio=98 prev_state=R ==> next_comm=kgsl_worker_thr next_pid=259 next_prio=97 + <...>-2048 (-----) [000] d..2 14594.813249: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=FastMixer next_pid=1238 next_prio=96 + <...>-14655 (-----) [006] d..2 14594.813263: sched_switch: prev_comm=DialerExecutors prev_pid=14655 prev_prio=130 prev_state=R+ ==> next_comm=smem_native_lpa next_pid=88 next_prio=98 + <...>-661 (-----) [002] d..2 14594.813265: sched_switch: prev_comm=sf prev_pid=661 prev_prio=97 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=116 + <...>-259 (-----) [007] d..2 14594.813265: sched_switch: prev_comm=kgsl_worker_thr prev_pid=259 prev_prio=97 prev_state=S ==> next_comm=kworker/7:1 next_pid=7092 next_prio=120 + kworker/7:1-7092 ( 7092) [007] d..2 14594.813271: sched_switch: prev_comm=kworker/7:1 prev_pid=7092 prev_prio=120 prev_state=S ==> next_comm=system next_pid=108 next_prio=120 + <...>-108 (-----) [007] .... 14594.813275: ion_heap_shrink: heap_name=system, len=9469952, total_allocated=189620224 + <...>-88 (-----) [006] d..2 14594.813294: sched_switch: prev_comm=smem_native_lpa prev_pid=88 prev_prio=98 prev_state=S ==> next_comm=DialerExecutors next_pid=14655 next_prio=130 + <...>-625 (-----) [004] ...1 14594.813310: tracing_mark_write: B|625|updateInputFlinger + <...>-1238 (-----) [000] d..2 14594.813312: sched_switch: prev_comm=FastMixer prev_pid=1238 prev_prio=96 prev_state=S ==> next_comm=RenderThread next_pid=2048 next_prio=120 + <...>-661 (-----) [002] d..2 14594.813317: sched_switch: prev_comm=sf prev_pid=661 prev_prio=97 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=116 + <...>-14640 (-----) [005] d..2 14594.813319: sched_switch: prev_comm=DialerExecutors prev_pid=14640 prev_prio=130 prev_state=R ==> next_comm=DispSync next_pid=658 next_prio=97 + <...>-656 (-----) [002] ...1 14594.813336: tracing_mark_write: B|625|~GraphicBuffer + <...>-658 (-----) [005] d..2 14594.813345: sched_switch: prev_comm=DispSync prev_pid=658 prev_prio=97 prev_state=S ==> next_comm=DialerExecutors next_pid=14640 next_prio=130 + <...>-656 (-----) [002] ...1 14594.813345: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813353: tracing_mark_write: B|625|~GraphicBuffer + <...>-2048 (-----) [000] d..2 14594.813358: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=FastMixer next_pid=1238 next_prio=96 + <...>-656 (-----) [002] ...1 14594.813364: tracing_mark_write: B|625|~GraphicBuffer + <...>-5281 (-----) [001] d..2 14594.813369: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=Binder:10691_B next_pid=18733 next_prio=110 + <...>-656 (-----) [002] ...1 14594.813372: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813380: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813391: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813398: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813408: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813416: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813424: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813432: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] .n.1 14594.813443: tracing_mark_write: B|625|~GraphicBuffer + <...>-1238 (-----) [000] d..2 14594.813464: sched_switch: prev_comm=FastMixer prev_pid=1238 prev_prio=96 prev_state=S ==> next_comm=RenderThread next_pid=2048 next_prio=120 + <...>-5281 (-----) [002] d..2 14594.813525: sched_switch: prev_comm=writer prev_pid=5281 prev_prio=96 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=116 + <...>-656 (-----) [002] ...1 14594.813544: tracing_mark_write: B|625|~GraphicBuffer + <...>-656 (-----) [002] ...1 14594.813557: tracing_mark_write: B|625|~GraphicBuffer + <...>-2048 (-----) [000] d..2 14594.813594: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=Binder:1368_15 next_pid=3359 next_prio=120 + <...>-18733 (-----) [001] ...2 14594.813635: binder_set_priority: proc=1368 thread=3514 old=120 => new=110 desired=110 + <...>-656 (-----) [002] .... 14594.813637: binder_set_priority: proc=625 thread=656 old=116 => new=120 desired=120 + <...>-108 (-----) [007] d..2 14594.813646: sched_switch: prev_comm=system prev_pid=108 prev_prio=120 prev_state=R+ ==> next_comm=android.anim next_pid=1398 next_prio=116 + <...>-625 (-----) [004] ...1 14594.813646: tracing_mark_write: B|625|onMessageReceived + <...>-625 (-----) [004] ...1 14594.813649: tracing_mark_write: B|625|handleMessageRefresh + <...>-625 (-----) [004] ...1 14594.813651: tracing_mark_write: B|625|preComposition + <...>-625 (-----) [004] ...1 14594.813693: tracing_mark_write: B|625|rebuildLayerStacks + <...>-625 (-----) [004] ...1 14594.813696: tracing_mark_write: B|625|rebuildLayerStacks VR Dirty + <...>-625 (-----) [004] ...1 14594.813701: tracing_mark_write: B|625|computeVisibleRegions + <...>-1398 (-----) [007] d..2 14594.813718: sched_switch: prev_comm=android.anim prev_pid=1398 prev_prio=116 prev_state=S ==> next_comm=system next_pid=108 next_prio=120 + <...>-108 (-----) [007] d..2 14594.813739: sched_switch: prev_comm=system prev_pid=108 prev_prio=120 prev_state=R+ ==> next_comm=android.anim next_pid=1398 next_prio=116 + <...>-1695 (-----) [002] d..2 14594.813970: sched_switch: prev_comm=InputDispatcher prev_pid=1695 prev_prio=112 prev_state=S ==> next_comm=system next_pid=108 next_prio=120 + <...>-1398 (-----) [007] ...1 14594.814029: tracing_mark_write: B|1368|wmLayout + <...>-1398 (-----) [007] ...1 14594.814033: tracing_mark_write: B|1368|performSurfacePlacement + <...>-1398 (-----) [007] ...1 14594.814040: tracing_mark_write: B|1368|applySurfaceChanges + <...>-1398 (-----) [007] ...1 14594.814043: tracing_mark_write: B|1368|openSurfaceTransaction + <...>-1398 (-----) [007] ...1 14594.814063: tracing_mark_write: B|1368|performLayout + <...>-625 (-----) [004] ...1 14594.814119: tracing_mark_write: B|625|calculateWorkingSet + <...>-1398 (-----) [007] ...1 14594.814241: tracing_mark_write: B|1368|layoutInputConsumer + <...>-2048 (-----) [000] ...1 14594.814260: tracing_mark_write: B|1803|prepareTree + <...>-1398 (-----) [007] ...1 14594.814263: tracing_mark_write: B|1368|applyPostLayoutPolicy + <...>-2048 (-----) [000] d..2 14594.814408: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R ==> next_comm=Binder:1368_15 next_pid=3359 next_prio=120 + <...>-625 (-----) [004] ...1 14594.814411: tracing_mark_write: B|625|prepare + <...>-625 (-----) [004] ...1 14594.814428: tracing_mark_write: B|625|HIDL::IComposerClient::executeCommands_2_2::client + <...>-2048 (-----) [000] d..2 14594.814533: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=ndroid.systemui next_pid=1803 next_prio=120 + <...>-1803 (-----) [000] d..2 14594.814558: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=RenderThread next_pid=2048 next_prio=120 + <...>-2048 (-----) [000] d..2 14594.814572: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=ndroid.systemui next_pid=1803 next_prio=120 + <...>-625 (-----) [004] ...2 14594.814589: binder_set_priority: proc=627 thread=627 old=97 => new=98 desired=98 + <...>-108 (-----) [002] d..2 14594.814650: sched_switch: prev_comm=system prev_pid=108 prev_prio=120 prev_state=R+ ==> next_comm=composer@2.2-se next_pid=627 next_prio=98 + <...>-625 (-----) [004] d..2 14594.814664: sched_switch: prev_comm=surfaceflinger prev_pid=625 prev_prio=98 prev_state=S ==> next_comm=ashmemd next_pid=854 next_prio=129 + <...>-1398 (-----) [007] ...1 14594.814723: tracing_mark_write: B|1368|applyWindowSurfaceChanges + <...>-854 (-----) [004] .... 14594.814746: binder_set_priority: proc=854 thread=854 old=129 => new=120 desired=120 + <...>-854 (-----) [004] d..2 14594.814757: sched_switch: prev_comm=ashmemd prev_pid=854 prev_prio=120 prev_state=R+ ==> next_comm=highpool[0] next_pid=3493 next_prio=129 + <...>-1803 (-----) [000] d..2 14594.814763: sched_switch: prev_comm=ndroid.systemui prev_pid=1803 prev_prio=120 prev_state=S ==> next_comm=RenderThread next_pid=2048 next_prio=120 + <...>-18733 (-----) [001] d..1 14594.814819: mm_filemap_delete_from_page_cache: dev 0:1 ino 3ce5e7 page=0000000083f10c7a pfn=1298474 ofs=0 + <...>-2048 (-----) [000] ...1 14594.814842: tracing_mark_write: B|1803|dequeueBuffer + <...>-1398 (-----) [007] ...1 14594.814850: tracing_mark_write: F|1368|launching: com.google.android.dialer|0 + <...>-1398 (-----) [007] ...1 14594.814855: tracing_mark_write: B|1368|MetricsLogger:launchObserverNotifyActivityLaunchFinished + <...>-1398 (-----) [007] ...1 14594.814857: tracing_mark_write: B|1368|MetricsLogger:convertActivityRecordToProto + <...>-2048 (-----) [000] d..2 14594.814905: sched_switch: prev_comm=RenderThread prev_pid=2048 prev_prio=120 prev_state=R+ ==> next_comm=Binder:625_1 next_pid=656 next_prio=120 + <...>-1410 (-----) [006] .... 14592.997816: mm_filemap_add_to_page_cache: dev 253:6 ino b785 page=00000000615a8f24 pfn=1134764 ofs=0 + <...>-1410 (-----) [006] .... 14592.997831: mm_filemap_add_to_page_cache: dev 253:6 ino b785 page=000000008768a58f pfn=1134751 ofs=4096 + + <...>-18733 (-----) [001] .... 14594.814914: binder_set_priority: proc=10691 thread=18733 old=110 => new=120 desired=120 + <...>-14655 (-----) [006] d..2 14594.814932: sched_switch: prev_comm=DialerExecutors prev_pid=14655 prev_prio=130 prev_state=R ==> next_comm=.android.dialer next_pid=14607 next_prio=110 + <...>-656 (-----) [000] ...1 14594.814948: tracing_mark_write: B|625|dequeueBuffer + <...>-3514 (-----) [001] .... 14594.814954: binder_set_priority: proc=1368 thread=3514 old=110 => new=120 desired=120 + <...>-656 (-----) [000] ...1 14594.814963: tracing_mark_write: B|625|NavigationBar0#0: 2 + <...>-14607 (-----) [006] ...2 14594.815022: binder_set_priority: proc=1368 thread=3514 old=120 => new=110 desired=110 + <...>-1398 (-----) [007] ...1 14594.815039: tracing_mark_write: B|1368|prepareSurfaces + <...>-14607 (-----) [006] d..2 14594.815041: sched_switch: prev_comm=.android.dialer prev_pid=14607 prev_prio=110 prev_state=S ==> next_comm=DialerExecutors next_pid=14655 next_prio=130 + <...>-3493 (-----) [004] d..2 14594.815057: sched_switch: prev_comm=highpool[0] prev_pid=3493 prev_prio=129 prev_state=R ==> next_comm=Binder:1368_18 next_pid=3514 next_prio=110 + <...>-2048 (-----) [000] ...1 14594.815088: tracing_mark_write: B|1803|HWC release fence 45750 has signaled + <...>-2048 (-----) [000] ...1 14594.815119: tracing_mark_write: B|1803|eglBeginFrame + <...>-14655 (-----) [006] d..2 14594.815190: sched_switch: prev_comm=DialerExecutors prev_pid=14655 prev_prio=130 prev_state=R ==> next_comm=crtc_commit:97 next_pid=301 next_prio=83 + <...>-3514 (-----) [004] .... 14594.815193: binder_set_priority: proc=1368 thread=3514 old=110 => new=120 desired=120 + <...>-1398 (-----) [007] ...1 14594.815322: tracing_mark_write: B|1368|closeSurfaceTransaction + <...>-3493 (-----) [004] .... 14594.815353: mm_filemap_add_to_page_cache: dev 253:6 ino 113b page=0000000069e2b98a pfn=628464 ofs=2723840 + <...>-1398 (-----) [007] ...2 14594.815393: binder_set_priority: proc=625 thread=656 old=120 => new=116 desired=116 + rcu_sched-8 ( 8) [007] d..2 14594.815449: sched_switch: prev_comm=rcu_sched prev_pid=8 prev_prio=120 prev_state=S ==> next_comm=Binder:625_1 next_pid=656 next_prio=116 diff --git a/startop/scripts/trace_analyzer/trace_analyzer b/startop/scripts/trace_analyzer/trace_analyzer new file mode 100755 index 000000000000..8c0396430c40 --- /dev/null +++ b/startop/scripts/trace_analyzer/trace_analyzer @@ -0,0 +1,42 @@ +#!/bin/bash +# Copyright (C) 2019 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +DIR="$( cd "$(dirname "$0")" ; pwd -P )" + +if [[ "$#" -lt 2 ]]; then + echo "Usage: $0 <filename.trace> <sqlite-filename.db>" >&2 + exit 1 +fi + +TRACE_FILENAME="$1" +SQLITE_FILENAME="$2" + +#echo "Trace filename: $TRACE_FILENAME" +#echo "SQLite filename: $SQLITE_FILENAME" + +if ! [[ -f "$TRACE_FILENAME" ]]; then + echo "Error: Trace '$TRACE_FILENAME' does not exist." >&2 + exit 1 +fi + +if ! "$DIR/trace_analyzer.py" "$SQLITE_FILENAME" "$TRACE_FILENAME" > /dev/null; then + echo "Fatal: trace_analyzer.py failed, aborting." >&2 + exit 1 +fi + +if ! "$DIR/run-sql-queries" "$SQLITE_FILENAME"; then + echo "Fatal: Failed to run sql queries, aborting." >&2 + exit 1 +fi diff --git a/startop/scripts/trace_analyzer/trace_analyzer.py b/startop/scripts/trace_analyzer/trace_analyzer.py new file mode 100755 index 000000000000..62ae018a9986 --- /dev/null +++ b/startop/scripts/trace_analyzer/trace_analyzer.py @@ -0,0 +1,51 @@ +#!/usr/bin/python3 +# Copyright (C) 2019 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import re +import sys +import argparse + +from lib.trace2db import Trace2Db + +# This script requires 'sqlalchemy' to access the sqlite3 database. +# +# $> sudo apt-get install python3-pip +# $> pip3 install --user sqlalchemy +# + +def main(argv): + parser = argparse.ArgumentParser(description='Convert ftrace/systrace file into sqlite3 db.') + parser.add_argument('db_filename', metavar='sql_filename.db', type=str, + help='path to sqlite3 db filename') + parser.add_argument('trace_filename', metavar='systrace.ftrace', type=str, + help='path to ftrace/systrace filename') + parser.add_argument('--limit', type=int, help='limit the number of entries parsed [for debugging]') + + args = parser.parse_args() + + db_filename = args.db_filename + trace_filename = args.trace_filename + + trace2db = Trace2Db(db_filename) + print("SQL Alchemy db initialized") + + # parse 'raw_ftrace_entries' table + count = trace2db.parse_file_into_db(trace_filename, limit=args.limit) + print("Count was ", count) + + return 0 + +if __name__ == '__main__': + main(sys.argv) diff --git a/startop/scripts/trace_analyzer/trace_analyzer_recursive b/startop/scripts/trace_analyzer/trace_analyzer_recursive new file mode 100755 index 000000000000..4d9ee0eec9b0 --- /dev/null +++ b/startop/scripts/trace_analyzer/trace_analyzer_recursive @@ -0,0 +1,78 @@ +#!/bin/bash +# Copyright (C) 2019 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +DIR="$( cd "$(dirname "$0")" ; pwd -P )" + +if [[ "$#" -lt 3 ]]; then + echo "Usage: $0 <trace-dir> <db-dir> <output.csv>" >&2 + exit 1 +fi + +simulate="n" + +TRACE_DIRNAME="$1" +SQLITE_DIRNAME="$2" +OUTPUT_FILENAME="$3" + +echo "Trace filename: $TRACE_DIRNAME" +echo "SQLite filename: $SQLITE_DIRNAME" + +if ! [[ -d "$TRACE_DIRNAME" ]]; then + echo "Error: Trace '$TRACE_DIRNAME' does not exist." >&2 + exit 1 +fi + +process_trace_file() { + local trace_filename="$1" + local db_dirname="$2" + local output_file="$3" + + local db_filename="$db_dirname/$(basename "$trace_filename").db" + + if [[ $simulate == y ]]; then + echo "$DIR/trace_analyzer.py" "$db_filename" "$trace_filename" "> /dev/null" + else + if ! "$DIR/trace_analyzer.py" "$db_filename" "$trace_filename" > /dev/null; then + echo "Fatal: trace_analyzer.py failed, aborting." >&2 + return 1 + fi + fi + + if [[ $simulate == y ]]; then + echo "$DIR/run-sql-queries" "$db_filename" ">> '$output_file'" + else + # append name of trace to CSV, so we can see where data came from + echo "; $trace_filename" >> "$output_file" + if ! "$DIR/run-sql-queries" "$db_filename" >> "$output_file"; then + echo "Fatal: Failed to run sql queries, aborting." >&2 + return 1 + fi + fi + + return 0 +} + +find "$TRACE_DIRNAME" -type f -name '*.trace' -print0 | +while IFS= read -r -d '' file; do + if [[ $file == *#*.trace && $file != *#1.trace ]]; then + echo "Skip $file" + continue + fi + + printf '%s\n' "$file" + process_trace_file "$file" "$SQLITE_DIRNAME" "$OUTPUT_FILENAME" +done + +echo "Done" diff --git a/startop/scripts/trace_analyzer/trace_analyzer_test.py b/startop/scripts/trace_analyzer/trace_analyzer_test.py new file mode 100644 index 000000000000..579529c6f6d5 --- /dev/null +++ b/startop/scripts/trace_analyzer/trace_analyzer_test.py @@ -0,0 +1,66 @@ +#!/usr/bin/env python3 +# +# Copyright 2019, The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +""" +Unit tests for trace_analyzer module. + +Install: + $> sudo apt-get install python3-pytest ## OR + $> pip install -U pytest +See also https://docs.pytest.org/en/latest/getting-started.html + +Usage: + $> pytest trace_analyzer_test.py + +See also https://docs.pytest.org/en/latest/usage.html +""" + +# global imports +import os +import sys + +DIR = os.path.abspath(os.path.dirname(__file__)) + +sys.path.append(os.path.dirname(DIR)) +import lib.cmd_utils as cmd_utils + +def test_trace_analyzer(tmpdir): + # Setup + bin = os.path.join(DIR, 'trace_analyzer') + systrace = os.path.join(DIR, 'test_fixtures/common_systrace') + db_file = tmpdir.mkdir('trace_analyzer').join('test.db') + + # Act + passed, output = cmd_utils.execute_arbitrary_command([bin, systrace, + str(db_file)], + timeout=300, + shell=False, + simulate=False) + + # Assert + assert passed + assert output == """\ +'blocked_iowait_duration_ms',\ +'process_name',\ +'launching_duration_ms',\ +'launching_started_timestamp_ms',\ +'launching_finished_timestamp_ms' +81.697999999960302375,\ +'com.google.android.dialer',\ +594.99400000095192808,\ +14594219.85600000061,\ +14594814.85000000149""" |