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

[PATCH v2 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

v1->v2:
- Set the executable bit for the script.
- Remove exclamation marks from error output.
- Fix a misspelling in a comment line.

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

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

-- 
2.17.1

[PATCH v2 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 100755 scripts/performance/dissect.py

diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
new file mode 100755
index 0000000000..8c2967d082
--- /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_annotate 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 v2 1/1] scripts/performance: Add dissect.py script

[Aleksandar Markovic]

[-- Attachment #1: Type: text/plain, Size: 8318 bytes --]

On Thursday, July 2, 2020, Ahmed Karaman <ahmedkhaledkaraman@gmail.com>
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
>
> 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>
> ---


A very good script! Hopefully there will be some script in near future that
will, for example, list all hepers used in the test program.

Reviewed-by: Aleksandar Markovic <aleksandar.qemu.devel@gmail.com>



>  scripts/performance/dissect.py | 165 +++++++++++++++++++++++++++++++++
>  1 file changed, 165 insertions(+)
>  create mode 100755 scripts/performance/dissect.py
>
> diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.
> py
> new file mode 100755
> index 0000000000..8c2967d082
> --- /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_annotate 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
>
>

[-- Attachment #2: Type: text/html, Size: 10798 bytes --]

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

[Ahmed Karaman]

On Thu, Jul 2, 2020 at 5:45 PM Aleksandar Markovic
<aleksandar.qemu.devel@gmail.com> wrote:
>
>
> A very good script! Hopefully there will be some script in near future that will, for example, list all hepers used in the test program.
>
> Reviewed-by: Aleksandar Markovic <aleksandar.qemu.devel@gmail.com>
>
>
Thanks Mr. Aleksandar. I Will start working on it.

Best regards,
Ahmed Karaman

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

[Philippe Mathieu-Daudé]

Hi Ahmed,

On 7/2/20 4:29 PM, 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
> 
> 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 100755 scripts/performance/dissect.py
> 
> diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
> new file mode 100755
> index 0000000000..8c2967d082
> --- /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_annotate 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
> +   """

Alignment off by 1 ;)

> +    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"]

Maybe "/path/to/callgrind.data" in the help?

> +                                + 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

1/ You use these files multiples time, please use a variable for each.
2/ This won't work on Windows
3/ This bypass the TMPDIR envirnoment variable
  a/ Darwin sets it to /var/folders/$user/$random/
  b/ Some users prefer to set TMPDIR on dedicated fast memory support

This is more portable:

  import tempfile

  annotated_path = os.path.join(tempfile.gettempdir(),
                                "callgrind_annotate.out")
  data_path = os.path.join(tempfile.gettempdir(), "callgrind.data")

Now, apparently both are temporary, so you can use a context manager
to get a temporary directory, and the context manager will remove it
when you are done.

Something like:

       with tempfile.TemporaryDirectory() as tmpdirname:
           annotated_path = os.path.join(tmpdirname,
                                         "callgrind_annotate.out")
           data_path = os.path.join(tmpdirname, "callgrind.data")

           with open(annotated_path, "w") as output:
                ....

No need to unlink/rmdir.

> +    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')

Maybe display a hint to the user? "Something went wrong. Is
callgrind_annotate installed?"

> +            output.close()

You used a context manager (with open ...) so no need to call close(),
it will be called when you are done with the context.

> +            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()

Here you didn't call close(), good :)

> +
> +    # 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')

No need for these unlink if using tempfile.TemporaryDirectory().

Regards,

Phil.

> +
> +
> +if __name__ == "__main__":
> +    main()
> 

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

[Ahmed Karaman]

On Wed, Jul 8, 2020 at 5:41 PM Philippe Mathieu-Daudé <philmd@redhat.com> wrote:
>
> Hi Ahmed,
>
> On 7/2/20 4:29 PM, 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
> >
> > 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 100755 scripts/performance/dissect.py
> >
> > diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py
> > new file mode 100755
> > index 0000000000..8c2967d082
> > --- /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_annotate 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
> > +   """
>
> Alignment off by 1 ;)

Thanks, didn't notice that!

>
> > +    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"]
>
> Maybe "/path/to/callgrind.data" in the help?

The user doesn't need to provide this path to the script. Callgrind
output is generated automatically for them.

>
> > +                                + 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
>
> 1/ You use these files multiples time, please use a variable for each.
> 2/ This won't work on Windows
> 3/ This bypass the TMPDIR envirnoment variable
>   a/ Darwin sets it to /var/folders/$user/$random/
>   b/ Some users prefer to set TMPDIR on dedicated fast memory support
>
> This is more portable:
>
>   import tempfile
>
>   annotated_path = os.path.join(tempfile.gettempdir(),
>                                 "callgrind_annotate.out")
>   data_path = os.path.join(tempfile.gettempdir(), "callgrind.data")
>
> Now, apparently both are temporary, so you can use a context manager
> to get a temporary directory, and the context manager will remove it
> when you are done.
>
> Something like:
>
>        with tempfile.TemporaryDirectory() as tmpdirname:
>            annotated_path = os.path.join(tmpdirname,
>                                          "callgrind_annotate.out")
>            data_path = os.path.join(tmpdirname, "callgrind.data")
>
>            with open(annotated_path, "w") as output:
>                 ....
>
> No need to unlink/rmdir.

This is a very nice trick! Thanks for the suggestion.

>
> > +    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')
>
> Maybe display a hint to the user? "Something went wrong. Is
> callgrind_annotate installed?"

callgrind_annotate is already installed by default with Valgrind. An
error happening here might be because of an empty callgrind output.

>
> > +            output.close()
>
> You used a context manager (with open ...) so no need to call close(),
> it will be called when you are done with the context.
>
> > +            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()
>
> Here you didn't call close(), good :)
>
> > +
> > +    # 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')
>
> No need for these unlink if using tempfile.TemporaryDirectory().
>
> Regards,
>
> Phil.
>
> > +
> > +
> > +if __name__ == "__main__":
> > +    main()
> >
>

Thanks a lot Mr. Philippe for your feedback. I'll post a v3 with the updates.

Best regards,
Ahmed Karaman

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

[no-reply]

Patchew URL: https://patchew.org/QEMU/20200702142942.4887-1-ahmedkhaledkaraman@gmail.com/



Hi,

This series failed build test on FreeBSD host. Please find the details below.

=== TEST SCRIPT BEGIN ===
#!/bin/bash
# Testing script will be invoked under the git checkout with
# HEAD pointing to a commit that has the patches applied on top of "base"
# branch
if qemu-system-x86_64 --help >/dev/null 2>&1; then
  QEMU=qemu-system-x86_64
elif /usr/libexec/qemu-kvm --help >/dev/null 2>&1; then
  QEMU=/usr/libexec/qemu-kvm
else
  exit 1
fi
make vm-build-freebsd J=21 QEMU=$QEMU
exit 0
=== TEST SCRIPT END ===




The full log is available at
http://patchew.org/logs/20200702142942.4887-1-ahmedkhaledkaraman@gmail.com/testing.FreeBSD/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com