[PATCH 0/1] Add Script for Dissecting QEMU Execution

[PATCH 0/1] Add Script for Dissecting QEMU Execution

[Ahmed Karaman]

Hi,

This series adds the dissect.py script which breaks down the execution
of QEMU into three main phases:
code generation, JIT execution, and helpers execution.

It prints the number of instructions executed by QEMU in each of these
three phases, plus the total number of executed instructions.

To learn more about how the script works and for further usage
instructions, please check the "Dissecting QEMU Into Three Main Parts"
report posted as part of the "TCG Continuous Benchmarking" GSoC project.

Report link:
https://lists.nongnu.org/archive/html/qemu-devel/2020-06/msg09441.html

Best regards,
Ahmed Karaman

Ahmed Karaman (1):
  scripts/performance: Add dissect.py script

 scripts/performance/dissect.py | 165 +++++++++++++++++++++++++++++++++
 1 file changed, 165 insertions(+)
 create mode 100644 scripts/performance/dissect.py

-- 
2.17.1

[PATCH 1/1] scripts/performance: Add dissect.py script

[Ahmed Karaman]

Python script that dissects QEMU execution into three main phases:
code generation, JIT execution and helpers execution.

Syntax:
dissect.py [-h] -- <qemu executable> [<qemu executable options>] \
                 <target executable> [<target executable options>]

[-h] - Print the script arguments help message.

Example of usage:
dissect.py -- qemu-arm coulomb_double-arm

Example output:
Total Instructions:        4,702,865,362

Code Generation:             115,819,309	 2.463%
JIT Execution:             1,081,980,528	23.007%
Helpers:                   3,505,065,525	74.530%

Signed-off-by: Ahmed Karaman <ahmedkhaledkaraman@gmail.com>
---
 scripts/performance/dissect.py | 165 +++++++++++++++++++++++++++++++++
 1 file changed, 165 insertions(+)
 create mode 100644 scripts/performance/dissect.py

diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
new file mode 100644
index 0000000000..26121e4a43
--- /dev/null
+++ b/scripts/performance/dissect.py
@@ -0,0 +1,165 @@
+#!/usr/bin/env python3
+
+#  Print the percentage of instructions spent in each phase of QEMU
+#  execution.
+#
+#  Syntax:
+#  dissect.py [-h] -- <qemu executable> [<qemu executable options>] \
+#                   <target executable> [<target executable options>]
+#
+#  [-h] - Print the script arguments help message.
+#
+#  Example of usage:
+#  dissect.py -- qemu-arm coulomb_double-arm
+#
+#  This file is a part of the project "TCG Continuous Benchmarking".
+#
+#  Copyright (C) 2020  Ahmed Karaman <ahmedkhaledkaraman@gmail.com>
+#  Copyright (C) 2020  Aleksandar Markovic <aleksandar.qemu.devel@gmail.com>
+#
+#  This program is free software: you can redistribute it and/or modify
+#  it under the terms of the GNU General Public License as published by
+#  the Free Software Foundation, either version 2 of the License, or
+#  (at your option) any later version.
+#
+#  This program is distributed in the hope that it will be useful,
+#  but WITHOUT ANY WARRANTY; without even the implied warranty of
+#  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+#  GNU General Public License for more details.
+#
+#  You should have received a copy of the GNU General Public License
+#  along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+import argparse
+import os
+import subprocess
+import sys
+
+
+def get_JIT_line(callgrind_data):
+    """
+    Search for the first instance of the JIT call in
+    the callgrind_annoutate output when ran using --tree=caller
+    This is equivalent to the self number of instructions of JIT.
+
+    Parameters:
+    callgrind_data (list): callgrind_annotate output
+
+    Returns:
+    (int): Line number
+   """
+    line = -1
+    for i in range(len(callgrind_data)):
+        if callgrind_data[i].strip('\n') and \
+                callgrind_data[i].split()[-1] == "[???]":
+            line = i
+            break
+    if line == -1:
+        sys.exit("Couldn't locate the JIT call ... Exiting!")
+    return line
+
+
+def main():
+    # Parse the command line arguments
+    parser = argparse.ArgumentParser(
+        usage='dissect.py [-h] -- '
+        '<qemu executable> [<qemu executable options>] '
+        '<target executable> [<target executable options>]')
+
+    parser.add_argument('command', type=str, nargs='+', help=argparse.SUPPRESS)
+
+    args = parser.parse_args()
+
+    # Extract the needed variables from the args
+    command = args.command
+
+    # Insure that valgrind is installed
+    check_valgrind = subprocess.run(
+        ["which", "valgrind"], stdout=subprocess.DEVNULL)
+    if check_valgrind.returncode:
+        sys.exit("Please install valgrind before running the script!")
+
+    # Run callgrind
+    callgrind = subprocess.run((["valgrind",
+                                 "--tool=callgrind",
+                                 "--callgrind-out-file=/tmp/callgrind.data"]
+                                + command),
+                               stdout=subprocess.DEVNULL,
+                               stderr=subprocess.PIPE)
+    if callgrind.returncode:
+        sys.exit(callgrind.stderr.decode("utf-8"))
+
+    # Save callgrind_annotate output to /tmp/callgrind_annotate.out
+    with open("/tmp/callgrind_annotate.out", "w") as output:
+        callgrind_annotate = subprocess.run(
+            ["callgrind_annotate", "/tmp/callgrind.data", "--tree=caller"],
+            stdout=output,
+            stderr=subprocess.PIPE)
+        if callgrind_annotate.returncode:
+            os.unlink('/tmp/callgrind.data')
+            output.close()
+            os.unlink('/tmp/callgrind_annotate.out')
+            sys.exit(callgrind_annotate.stderr.decode("utf-8"))
+
+    # Read the callgrind_annotate output to callgrind_data[]
+    callgrind_data = []
+    with open('/tmp/callgrind_annotate.out', 'r') as data:
+        callgrind_data = data.readlines()
+
+    # Line number with the total number of instructions
+    total_instructions_line_number = 20
+    # Get the total number of instructions
+    total_instructions_line_data = \
+        callgrind_data[total_instructions_line_number]
+    total_instructions = total_instructions_line_data.split()[0]
+    total_instructions = int(total_instructions.replace(',', ''))
+
+    # Line number with the JIT self number of instructions
+    JIT_self_instructions_line_number = get_JIT_line(callgrind_data)
+    # Get the JIT self number of instructions
+    JIT_self_instructions_line_data = \
+        callgrind_data[JIT_self_instructions_line_number]
+    JIT_self_instructions = JIT_self_instructions_line_data.split()[0]
+    JIT_self_instructions = int(JIT_self_instructions.replace(',', ''))
+
+    # Line number with the JIT self + inclusive number of instructions
+    # It's the line above the first JIT call when running with --tree=caller
+    JIT_total_instructions_line_number = JIT_self_instructions_line_number - 1
+    # Get the JIT self + inclusive number of instructions
+    JIT_total_instructions_line_data = \
+        callgrind_data[JIT_total_instructions_line_number]
+    JIT_total_instructions = JIT_total_instructions_line_data.split()[0]
+    JIT_total_instructions = int(JIT_total_instructions.replace(',', ''))
+
+    # Calculate number of instructions in helpers and code generation
+    helpers_instructions = JIT_total_instructions - JIT_self_instructions
+    code_generation_instructions = total_instructions - JIT_total_instructions
+
+    # Print results (Insert commas in large numbers)
+    # Print total number of instructions
+    print('{:<20}{:>20}\n'.
+          format("Total Instructions:",
+                 format(total_instructions, ',')))
+    # Print code generation instructions and percentage
+    print('{:<20}{:>20}\t{:>6.3f}%'.
+          format("Code Generation:",
+                 format(code_generation_instructions, ","),
+                 (code_generation_instructions / total_instructions) * 100))
+    # Print JIT instructions and percentage
+    print('{:<20}{:>20}\t{:>6.3f}%'.
+          format("JIT Execution:",
+                 format(JIT_self_instructions, ","),
+                 (JIT_self_instructions / total_instructions) * 100))
+    # Print helpers instructions and percentage
+    print('{:<20}{:>20}\t{:>6.3f}%'.
+          format("Helpers:",
+                 format(helpers_instructions, ","),
+                 (helpers_instructions/total_instructions)*100))
+
+    # Remove intermediate files
+    os.unlink('/tmp/callgrind.data')
+    os.unlink('/tmp/callgrind_annotate.out')
+
+
+if __name__ == "__main__":
+    main()
-- 
2.17.1

Re: [PATCH 1/1] scripts/performance: Add dissect.py script

[Eric Blake]

On 7/1/20 8:04 AM, Ahmed Karaman wrote:
> Python script that dissects QEMU execution into three main phases:
> code generation, JIT execution and helpers execution.
> 
> Syntax:
> dissect.py [-h] -- <qemu executable> [<qemu executable options>] \
>                   <target executable> [<target executable options>]
> 
> [-h] - Print the script arguments help message.
> 
> Example of usage:
> dissect.py -- qemu-arm coulomb_double-arm

Given the example usage...

> 
> Example output:
> Total Instructions:        4,702,865,362
> 
> Code Generation:             115,819,309	 2.463%
> JIT Execution:             1,081,980,528	23.007%
> Helpers:                   3,505,065,525	74.530%
> 
> Signed-off-by: Ahmed Karaman <ahmedkhaledkaraman@gmail.com>
> ---
>   scripts/performance/dissect.py | 165 +++++++++++++++++++++++++++++++++
>   1 file changed, 165 insertions(+)
>   create mode 100644 scripts/performance/dissect.py
> 
> diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
> new file mode 100644

...this should have the executable bit set.


> +def get_JIT_line(callgrind_data):
> +    """
> +    Search for the first instance of the JIT call in
> +    the callgrind_annoutate output when ran using --tree=caller

annotate

> +    This is equivalent to the self number of instructions of JIT.
> +
> +    Parameters:
> +    callgrind_data (list): callgrind_annotate output
> +
> +    Returns:
> +    (int): Line number
> +   """
> +    line = -1
> +    for i in range(len(callgrind_data)):
> +        if callgrind_data[i].strip('\n') and \
> +                callgrind_data[i].split()[-1] == "[???]":
> +            line = i
> +            break
> +    if line == -1:
> +        sys.exit("Couldn't locate the JIT call ... Exiting!")

We tend to avoid ! at the end of error messages (it can come across as 
shouting at the user).

> +    return line
> +
> +
> +def main():
> +    # Parse the command line arguments
> +    parser = argparse.ArgumentParser(
> +        usage='dissect.py [-h] -- '
> +        '<qemu executable> [<qemu executable options>] '
> +        '<target executable> [<target executable options>]')
> +
> +    parser.add_argument('command', type=str, nargs='+', help=argparse.SUPPRESS)
> +
> +    args = parser.parse_args()
> +
> +    # Extract the needed variables from the args
> +    command = args.command
> +
> +    # Insure that valgrind is installed
> +    check_valgrind = subprocess.run(
> +        ["which", "valgrind"], stdout=subprocess.DEVNULL)
> +    if check_valgrind.returncode:
> +        sys.exit("Please install valgrind before running the script!")

and again

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Re: [PATCH 1/1] scripts/performance: Add dissect.py script

[Ahmed Karaman]

On Wed, Jul 1, 2020 at 3:41 PM Eric Blake <eblake@redhat.com> wrote:
>
> On 7/1/20 8:04 AM, Ahmed Karaman wrote:
> > Python script that dissects QEMU execution into three main phases:
> > code generation, JIT execution and helpers execution.
> >
> > Syntax:
> > dissect.py [-h] -- <qemu executable> [<qemu executable options>] \
> >                   <target executable> [<target executable options>]
> >
> > [-h] - Print the script arguments help message.
> >
> > Example of usage:
> > dissect.py -- qemu-arm coulomb_double-arm
>
> Given the example usage...
>
> >
> > Example output:
> > Total Instructions:        4,702,865,362
> >
> > Code Generation:             115,819,309       2.463%
> > JIT Execution:             1,081,980,528      23.007%
> > Helpers:                   3,505,065,525      74.530%
> >
> > Signed-off-by: Ahmed Karaman <ahmedkhaledkaraman@gmail.com>
> > ---
> >   scripts/performance/dissect.py | 165 +++++++++++++++++++++++++++++++++
> >   1 file changed, 165 insertions(+)
> >   create mode 100644 scripts/performance/dissect.py
> >
> > diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
> > new file mode 100644
>
> ...this should have the executable bit set.
Thanks Mr. Eric, I don't know why I always forget doing this before
sending the patch. Will do it in V2.
>
>
> > +def get_JIT_line(callgrind_data):
> > +    """
> > +    Search for the first instance of the JIT call in
> > +    the callgrind_annoutate output when ran using --tree=caller
>
> annotate
Thanks.

>
> > +    This is equivalent to the self number of instructions of JIT.
> > +
> > +    Parameters:
> > +    callgrind_data (list): callgrind_annotate output
> > +
> > +    Returns:
> > +    (int): Line number
> > +   """
> > +    line = -1
> > +    for i in range(len(callgrind_data)):
> > +        if callgrind_data[i].strip('\n') and \
> > +                callgrind_data[i].split()[-1] == "[???]":
> > +            line = i
> > +            break
> > +    if line == -1:
> > +        sys.exit("Couldn't locate the JIT call ... Exiting!")
>
> We tend to avoid ! at the end of error messages (it can come across as
> shouting at the user).
Yeah right, Will remove the exclamations.
>
> > +    return line
> > +
> > +
> > +def main():
> > +    # Parse the command line arguments
> > +    parser = argparse.ArgumentParser(
> > +        usage='dissect.py [-h] -- '
> > +        '<qemu executable> [<qemu executable options>] '
> > +        '<target executable> [<target executable options>]')
> > +
> > +    parser.add_argument('command', type=str, nargs='+', help=argparse.SUPPRESS)
> > +
> > +    args = parser.parse_args()
> > +
> > +    # Extract the needed variables from the args
> > +    command = args.command
> > +
> > +    # Insure that valgrind is installed
> > +    check_valgrind = subprocess.run(
> > +        ["which", "valgrind"], stdout=subprocess.DEVNULL)
> > +    if check_valgrind.returncode:
> > +        sys.exit("Please install valgrind before running the script!")
>
> and again
Noted.
>
> --
> Eric Blake, Principal Software Engineer
> Red Hat, Inc.           +1-919-301-3226
> Virtualization:  qemu.org | libvirt.org
>
Thanks for your feedback Mr. Eric.

Best regards,
Ahmed Karaman