diff options
| -rw-r--r-- | python/qemu/machine.py | 174 | ||||
| -rw-r--r-- | python/qemu/qmp.py | 67 | ||||
| -rwxr-xr-x | scripts/performance/dissect.py | 166 | ||||
| -rwxr-xr-x | scripts/render_block_graph.py | 7 | ||||
| -rw-r--r-- | tests/acceptance/boot_linux_console.py | 14 | ||||
| -rw-r--r-- | tests/acceptance/linux_ssh_mips_malta.py | 2 | ||||
| -rw-r--r-- | tests/qemu-iotests/iotests.py | 9 |
7 files changed, 368 insertions, 71 deletions
diff --git a/python/qemu/machine.py b/python/qemu/machine.py index c25f0b4..80c4d4a 100644 --- a/python/qemu/machine.py +++ b/python/qemu/machine.py @@ -22,6 +22,7 @@ import logging import os import subprocess import shutil +import signal import socket import tempfile from typing import Optional, Type @@ -49,17 +50,10 @@ class QEMUMachineAddDeviceError(QEMUMachineError): """ -class MonitorResponseError(qmp.QMPError): +class AbnormalShutdown(QEMUMachineError): """ - Represents erroneous QMP monitor reply + Exception raised when a graceful shutdown was requested, but not performed. """ - def __init__(self, reply): - try: - desc = reply["error"]["desc"] - except KeyError: - desc = reply - super().__init__(desc) - self.reply = reply class QEMUMachine: @@ -127,6 +121,7 @@ class QEMUMachine: self._console_address = None self._console_socket = None self._remove_files = [] + self._user_killed = False self._console_log_path = console_log if self._console_log_path: # In order to log the console, buffering needs to be enabled. @@ -294,6 +289,19 @@ class QEMUMachine: self._qmp.accept() def _post_shutdown(self): + """ + Called to cleanup the VM instance after the process has exited. + May also be called after a failed launch. + """ + # Comprehensive reset for the failed launch case: + self._early_cleanup() + + if self._qmp: + self._qmp.close() + self._qmp = None + + self._load_io_log() + if self._qemu_log_file is not None: self._qemu_log_file.close() self._qemu_log_file = None @@ -307,6 +315,19 @@ class QEMUMachine: while len(self._remove_files) > 0: self._remove_if_exists(self._remove_files.pop()) + exitcode = self.exitcode() + if (exitcode is not None and exitcode < 0 + and not (self._user_killed and exitcode == -signal.SIGKILL)): + msg = 'qemu received signal %i; command: "%s"' + if self._qemu_full_args: + command = ' '.join(self._qemu_full_args) + else: + command = '' + LOG.warning(msg, -int(exitcode), command) + + self._user_killed = False + self._launched = False + def launch(self): """ Launch the VM and make sure we cleanup and expose the @@ -322,7 +343,7 @@ class QEMUMachine: self._launch() self._launched = True except: - self.shutdown() + self._post_shutdown() LOG.debug('Error launching VM') if self._qemu_full_args: @@ -348,19 +369,12 @@ class QEMUMachine: close_fds=False) self._post_launch() - def wait(self): - """ - Wait for the VM to power off + def _early_cleanup(self) -> None: """ - self._popen.wait() - if self._qmp: - self._qmp.close() - self._load_io_log() - self._post_shutdown() + Perform any cleanup that needs to happen before the VM exits. - def shutdown(self, has_quit=False, hard=False): - """ - Terminate the VM and clean up + May be invoked by both soft and hard shutdown in failover scenarios. + Called additionally by _post_shutdown for comprehensive cleanup. """ # If we keep the console socket open, we may deadlock waiting # for QEMU to exit, while QEMU is waiting for the socket to @@ -369,37 +383,105 @@ class QEMUMachine: self._console_socket.close() self._console_socket = None - if self.is_running(): - if hard: - self._popen.kill() - elif self._qmp: - try: - if not has_quit: - self._qmp.cmd('quit') - self._qmp.close() - self._popen.wait(timeout=3) - except: - self._popen.kill() - self._popen.wait() + def _hard_shutdown(self) -> None: + """ + Perform early cleanup, kill the VM, and wait for it to terminate. - self._load_io_log() - self._post_shutdown() + :raise subprocess.Timeout: When timeout is exceeds 60 seconds + waiting for the QEMU process to terminate. + """ + self._early_cleanup() + self._popen.kill() + self._popen.wait(timeout=60) - exitcode = self.exitcode() - if exitcode is not None and exitcode < 0 and \ - not (exitcode == -9 and hard): - msg = 'qemu received signal %i: %s' - if self._qemu_full_args: - command = ' '.join(self._qemu_full_args) - else: - command = '' - LOG.warning(msg, -int(exitcode), command) + def _soft_shutdown(self, has_quit: bool = False, + timeout: Optional[int] = 3) -> None: + """ + Perform early cleanup, attempt to gracefully shut down the VM, and wait + for it to terminate. - self._launched = False + :param has_quit: When True, don't attempt to issue 'quit' QMP command + :param timeout: Optional timeout in seconds for graceful shutdown. + Default 3 seconds, A value of None is an infinite wait. + + :raise ConnectionReset: On QMP communication errors + :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for + the QEMU process to terminate. + """ + self._early_cleanup() + + if self._qmp is not None: + if not has_quit: + # Might raise ConnectionReset + self._qmp.cmd('quit') + + # May raise subprocess.TimeoutExpired + self._popen.wait(timeout=timeout) + + def _do_shutdown(self, has_quit: bool = False, + timeout: Optional[int] = 3) -> None: + """ + Attempt to shutdown the VM gracefully; fallback to a hard shutdown. + + :param has_quit: When True, don't attempt to issue 'quit' QMP command + :param timeout: Optional timeout in seconds for graceful shutdown. + Default 3 seconds, A value of None is an infinite wait. + + :raise AbnormalShutdown: When the VM could not be shut down gracefully. + The inner exception will likely be ConnectionReset or + subprocess.TimeoutExpired. In rare cases, non-graceful termination + may result in its own exceptions, likely subprocess.TimeoutExpired. + """ + try: + self._soft_shutdown(has_quit, timeout) + except Exception as exc: + self._hard_shutdown() + raise AbnormalShutdown("Could not perform graceful shutdown") \ + from exc + + def shutdown(self, has_quit: bool = False, + hard: bool = False, + timeout: Optional[int] = 3) -> None: + """ + Terminate the VM (gracefully if possible) and perform cleanup. + Cleanup will always be performed. + + If the VM has not yet been launched, or shutdown(), wait(), or kill() + have already been called, this method does nothing. + + :param has_quit: When true, do not attempt to issue 'quit' QMP command. + :param hard: When true, do not attempt graceful shutdown, and + suppress the SIGKILL warning log message. + :param timeout: Optional timeout in seconds for graceful shutdown. + Default 3 seconds, A value of None is an infinite wait. + """ + if not self._launched: + return + + try: + if hard: + self._user_killed = True + self._hard_shutdown() + else: + self._do_shutdown(has_quit, timeout=timeout) + finally: + self._post_shutdown() def kill(self): + """ + Terminate the VM forcefully, wait for it to exit, and perform cleanup. + """ self.shutdown(hard=True) + def wait(self, timeout: Optional[int] = 3) -> None: + """ + Wait for the VM to power off and perform post-shutdown cleanup. + + :param timeout: Optional timeout in seconds. + Default 3 seconds, A value of None is an infinite wait. + """ + self.shutdown(has_quit=True, timeout=timeout) + def set_qmp_monitor(self, enabled=True): """ Set the QMP monitor. @@ -438,7 +520,7 @@ class QEMUMachine: if reply is None: raise qmp.QMPError("Monitor is closed") if "error" in reply: - raise MonitorResponseError(reply) + raise qmp.QMPResponseError(reply) return reply["return"] def get_qmp_event(self, wait=False): diff --git a/python/qemu/qmp.py b/python/qemu/qmp.py index e64b6b5..7935dab 100644 --- a/python/qemu/qmp.py +++ b/python/qemu/qmp.py @@ -12,13 +12,32 @@ import errno import socket import logging from typing import ( + Any, + cast, + Dict, Optional, TextIO, Type, + Tuple, + Union, ) from types import TracebackType +# QMPMessage is a QMP Message of any kind. +# e.g. {'yee': 'haw'} +# +# QMPReturnValue is the inner value of return values only. +# {'return': {}} is the QMPMessage, +# {} is the QMPReturnValue. +QMPMessage = Dict[str, Any] +QMPReturnValue = Dict[str, Any] + +InternetAddrT = Tuple[str, str] +UnixAddrT = str +SocketAddrT = Union[InternetAddrT, UnixAddrT] + + class QMPError(Exception): """ QMP base exception @@ -43,6 +62,25 @@ class QMPTimeoutError(QMPError): """ +class QMPProtocolError(QMPError): + """ + QMP protocol error; unexpected response + """ + + +class QMPResponseError(QMPError): + """ + Represents erroneous QMP monitor reply + """ + def __init__(self, reply: QMPMessage): + try: + desc = reply['error']['desc'] + except KeyError: + desc = reply + super().__init__(desc) + self.reply = reply + + class QEMUMonitorProtocol: """ Provide an API to connect to QEMU via QEMU Monitor Protocol (QMP) and then @@ -99,7 +137,10 @@ class QEMUMonitorProtocol: data = self.__sockfile.readline() if not data: return None - resp = json.loads(data) + # By definition, any JSON received from QMP is a QMPMessage, + # and we are asserting only at static analysis time that it + # has a particular shape. + resp: QMPMessage = json.loads(data) if 'event' in resp: self.logger.debug("<<< %s", resp) self.__events.append(resp) @@ -194,22 +235,18 @@ class QEMUMonitorProtocol: self.__sockfile = self.__sock.makefile(mode='r') return self.__negotiate_capabilities() - def cmd_obj(self, qmp_cmd): + def cmd_obj(self, qmp_cmd: QMPMessage) -> QMPMessage: """ Send a QMP command to the QMP Monitor. @param qmp_cmd: QMP command to be sent as a Python dict - @return QMP response as a Python dict or None if the connection has - been closed + @return QMP response as a Python dict """ self.logger.debug(">>> %s", qmp_cmd) - try: - self.__sock.sendall(json.dumps(qmp_cmd).encode('utf-8')) - except OSError as err: - if err.errno == errno.EPIPE: - return None - raise err + self.__sock.sendall(json.dumps(qmp_cmd).encode('utf-8')) resp = self.__json_read() + if resp is None: + raise QMPConnectError("Unexpected empty reply from server") self.logger.debug("<<< %s", resp) return resp @@ -233,9 +270,13 @@ class QEMUMonitorProtocol: Build and send a QMP command to the monitor, report errors if any """ ret = self.cmd(cmd, kwds) - if "error" in ret: - raise Exception(ret['error']['desc']) - return ret['return'] + if 'error' in ret: + raise QMPResponseError(ret) + if 'return' not in ret: + raise QMPProtocolError( + "'return' key not found in QMP response '{}'".format(str(ret)) + ) + return cast(QMPReturnValue, ret['return']) def pull_event(self, wait=False): """ diff --git a/scripts/performance/dissect.py b/scripts/performance/dissect.py new file mode 100755 index 0000000..bf24f50 --- /dev/null +++ b/scripts/performance/dissect.py @@ -0,0 +1,166 @@ +#!/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 +import tempfile + + +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.") + + # Save all intermediate files in a temporary directory + with tempfile.TemporaryDirectory() as tmpdirname: + # callgrind output file path + data_path = os.path.join(tmpdirname, "callgrind.data") + # callgrind_annotate output file path + annotate_out_path = os.path.join(tmpdirname, "callgrind_annotate.out") + + # Run callgrind + callgrind = subprocess.run((["valgrind", + "--tool=callgrind", + "--callgrind-out-file=" + data_path] + + command), + stdout=subprocess.DEVNULL, + stderr=subprocess.PIPE) + if callgrind.returncode: + sys.exit(callgrind.stderr.decode("utf-8")) + + # Save callgrind_annotate output + with open(annotate_out_path, "w") as output: + callgrind_annotate = subprocess.run( + ["callgrind_annotate", data_path, "--tree=caller"], + stdout=output, + stderr=subprocess.PIPE) + if callgrind_annotate.returncode: + sys.exit(callgrind_annotate.stderr.decode("utf-8")) + + # Read the callgrind_annotate output to callgrind_data[] + callgrind_data = [] + with open(annotate_out_path, '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)) + + +if __name__ == "__main__": + main() diff --git a/scripts/render_block_graph.py b/scripts/render_block_graph.py index 409b432..da6acf0 100755 --- a/scripts/render_block_graph.py +++ b/scripts/render_block_graph.py @@ -25,7 +25,10 @@ import json from graphviz import Digraph sys.path.append(os.path.join(os.path.dirname(__file__), '..', 'python')) -from qemu.machine import MonitorResponseError +from qemu.qmp import ( + QEMUMonitorProtocol, + QMPResponseError, +) def perm(arr): @@ -102,7 +105,7 @@ class LibvirtGuest(): reply = json.loads(subprocess.check_output(ar)) if 'error' in reply: - raise MonitorResponseError(reply) + raise QMPResponseError(reply) return reply['return'] diff --git a/tests/acceptance/boot_linux_console.py b/tests/acceptance/boot_linux_console.py index 67c3b2f..73cc69c 100644 --- a/tests/acceptance/boot_linux_console.py +++ b/tests/acceptance/boot_linux_console.py @@ -207,6 +207,8 @@ class BootLinuxConsole(LinuxKernelTest): 'Debian') exec_command_and_wait_for_pattern(self, 'reboot', 'reboot: Restarting system') + # Wait for VM to shut down gracefully + self.vm.wait() @skipUnless(os.getenv('AVOCADO_ALLOW_UNTRUSTED_CODE'), 'untrusted code') def test_mips64el_malta_5KEc_cpio(self): @@ -247,6 +249,8 @@ class BootLinuxConsole(LinuxKernelTest): '3.19.3.mtoman.20150408') exec_command_and_wait_for_pattern(self, 'reboot', 'reboot: Restarting system') + # Wait for VM to shut down gracefully + self.vm.wait() def do_test_mips_malta32el_nanomips(self, kernel_url, kernel_hash): kernel_path_xz = self.fetch_asset(kernel_url, asset_hash=kernel_hash) @@ -520,8 +524,7 @@ class BootLinuxConsole(LinuxKernelTest): 'Allwinner sun4i/sun5i') exec_command_and_wait_for_pattern(self, 'cat /proc/iomem', 'system-control@1c00000') - exec_command_and_wait_for_pattern(self, 'reboot', - 'reboot: Restarting system') + # cubieboard's reboot is not functioning; omit reboot test. def test_arm_cubieboard_sata(self): """ @@ -564,8 +567,7 @@ class BootLinuxConsole(LinuxKernelTest): 'Allwinner sun4i/sun5i') exec_command_and_wait_for_pattern(self, 'cat /proc/partitions', 'sda') - exec_command_and_wait_for_pattern(self, 'reboot', - 'reboot: Restarting system') + # cubieboard's reboot is not functioning; omit reboot test. def test_arm_orangepi(self): """ @@ -631,6 +633,8 @@ class BootLinuxConsole(LinuxKernelTest): 'system-control@1c00000') exec_command_and_wait_for_pattern(self, 'reboot', 'reboot: Restarting system') + # Wait for VM to shut down gracefully + self.vm.wait() def test_arm_orangepi_sd(self): """ @@ -680,6 +684,8 @@ class BootLinuxConsole(LinuxKernelTest): '3 packets transmitted, 3 packets received, 0% packet loss') exec_command_and_wait_for_pattern(self, 'reboot', 'reboot: Restarting system') + # Wait for VM to shut down gracefully + self.vm.wait() @skipUnless(os.getenv('AVOCADO_ALLOW_LARGE_STORAGE'), 'storage limited') @skipUnless(P7ZIP_AVAILABLE, '7z not installed') diff --git a/tests/acceptance/linux_ssh_mips_malta.py b/tests/acceptance/linux_ssh_mips_malta.py index 90d7f2f..25c5c5f 100644 --- a/tests/acceptance/linux_ssh_mips_malta.py +++ b/tests/acceptance/linux_ssh_mips_malta.py @@ -212,6 +212,8 @@ class LinuxSSH(Test): self.run_common_commands(wordsize) self.shutdown_via_ssh() + # Wait for VM to shut down gracefully + self.vm.wait() def test_mips_malta32eb_kernel3_2_0(self): """ diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py index 8b76040..3590ed7 100644 --- a/tests/qemu-iotests/iotests.py +++ b/tests/qemu-iotests/iotests.py @@ -35,13 +35,10 @@ import unittest # pylint: disable=import-error, wrong-import-position sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'python')) from qemu import qtest +from qemu.qmp import QMPMessage assert sys.version_info >= (3, 6) -# Type Aliases -QMPResponse = Dict[str, Any] - - # Use this logger for logging messages directly from the iotests module logger = logging.getLogger('qemu.iotests') logger.addHandler(logging.NullHandler()) @@ -561,7 +558,7 @@ class VM(qtest.QEMUQtestMachine): self._args.append(addr) return self - def hmp(self, command_line: str, use_log: bool = False) -> QMPResponse: + def hmp(self, command_line: str, use_log: bool = False) -> QMPMessage: cmd = 'human-monitor-command' kwargs = {'command-line': command_line} if use_log: @@ -582,7 +579,7 @@ class VM(qtest.QEMUQtestMachine): self.hmp(f'qemu-io {drive} "remove_break bp_{drive}"') def hmp_qemu_io(self, drive: str, cmd: str, - use_log: bool = False) -> QMPResponse: + use_log: bool = False) -> QMPMessage: """Write to a given drive using an HMP command""" return self.hmp(f'qemu-io {drive} "{cmd}"', use_log=use_log) |