awlsim-test

@@ -68,6 +68,7 @@ def usage():
 	print("                         default:     Keep project settings (default)")
 	print("                         all:         Enable all optimizers")
 	print("                         off:         Disable all optimizers")
+	print(" --insn-meas OUTFILE   Detailed instruction timing measurements")
 	print(" -L|--loglevel LVL     Set the log level:")
 	print("                       0: Log nothing")
 	print("                       1: Log errors")
@@ -149,23 +150,12 @@ def emitCpuDump(dump):
 		clearConsole()
 		writeStdout(dump)
 
-def emitSpeedDump(cpu):
-	dump = "S7 CPU speed:  %s stmt/s" % cpu.insnPerSecondHR
-	dump += " " * (79 - len(dump))
-	writeStdout("\x1B[2J\x1B[H" + dump + "\n")
-
-def cpuDumpCallback(cpu):
+def cpuBlockExitCallback(cpu):
 	global nextScreenUpdate
 	if cpu.now >= nextScreenUpdate:
 		nextScreenUpdate = cpu.now + 0.3
 		emitCpuDump(str(cpu))
 
-def cpuStatsCallback(cpu):
-	global nextScreenUpdate
-	if cpu.now >= nextScreenUpdate:
-		nextScreenUpdate = cpu.now + 1.0
-		emitSpeedDump(cpu)
-
 def assignCpuSpecs(cpuSpecs, projectCpuSpecs):
 	cpuSpecs.assignFrom(projectCpuSpecs)
 	if opt_nrAccus is not None:
@@ -198,6 +188,7 @@ def readInputFile(inputFile):
 	return project
 
 def run(inputFile):
+	insnMeas = None
 	s = None
 	try:
 		if cython_helper.shouldUseCython():
@@ -279,11 +270,8 @@ def run(inputFile):
 		cpu = s.getCPU()
 		assignCpuSpecs(cpu.getSpecs(), project.getCpuSpecs())
 		assignCpuConf(cpu.getConf(), project.getCpuConf())
-		if not opt_noCpuDump:
-			if opt_speedStats:
-				cpu.setBlockExitCallback(cpuStatsCallback, cpu)
-			elif opt_loglevel >= Logging.LOG_INFO:
-				cpu.setBlockExitCallback(cpuDumpCallback, cpu)
+		if not opt_noCpuDump and opt_loglevel >= Logging.LOG_INFO:
+			cpu.setBlockExitCallback(cpuBlockExitCallback, cpu)
 
 		# Download the program
 		printInfo("Initializing CPU...")
@@ -293,6 +281,10 @@ def run(inputFile):
 			s.loadLibraryBlock(libSel)
 		for parseTree in parseTrees:
 			s.load(parseTree)
+		s.build()
+
+		if opt_insnMeas:
+			insnMeas = cpu.setupInsnMeas()
 
 		# Run the program
 		s.startup()
@@ -310,7 +302,16 @@ def run(inputFile):
 		printError(e.getReport())
 		return ExitCodes.EXIT_ERR_SIM
 	except KeyboardInterrupt as e:
-		pass
+		if insnMeas:
+			if insnMeas.haveAnyMeasurements:
+				if opt_insnMeas == "-":
+					insnMeas.dump()
+				else:
+					with open(opt_insnMeas, "wb") as fd:
+						fd.write(insnMeas.dumpCSV().encode("UTF-8"))
+			else:
+				printError("Instruction timing measurement: Not enough samples.")
+				return ExitCodes.EXIT_ERR_OTHER
 	except MaintenanceRequest as e:
 		if e.requestType in (MaintenanceRequest.TYPE_SHUTDOWN,
 				     MaintenanceRequest.TYPE_STOP,
@@ -513,13 +514,13 @@ def main():
 	global opt_cycletime
 	global opt_maxRuntime
 	global opt_noCpuDump
-	global opt_speedStats
 	global opt_nrAccus
 	global opt_extInsns
 	global opt_obtemp
 	global opt_clockMem
 	global opt_mnemonics
 	global opt_optimizers
+	global opt_insnMeas
 	global opt_hwmods
 	global opt_hwinfos
 	global opt_loglevel
@@ -533,13 +534,13 @@ def main():
 	opt_cycletime = None
 	opt_maxRuntime = None
 	opt_noCpuDump = False
-	opt_speedStats = False
 	opt_nrAccus = None
 	opt_extInsns = None
 	opt_obtemp = None
 	opt_clockMem = None
 	opt_mnemonics = None
 	opt_optimizers = "default"
+	opt_insnMeas = None
 	opt_hwmods = []
 	opt_hwinfos = []
 	opt_loglevel = Logging.LOG_INFO
@@ -552,14 +553,15 @@ def main():
 
 	try:
 		(opts, args) = getopt.getopt(sys.argv[1:],
-			"hY:M:24qDSxt:T:m:O:H:I:P:L:cC:bi:R:W:",
+			"hY:M:24qDxt:T:m:O:H:I:P:L:cC:bi:R:W:",
 			[ "help", "cycle-limit=", "max-runtime=", "twoaccu", "fouraccu",
-			  "quiet", "no-cpu-dump", "speed-stats", "extended-insns",
+			  "quiet", "no-cpu-dump", "extended-insns",
 			  "obtemp=", "clock-mem=", "mnemonics=", "optimizers=",
 			  "hardware=", "hardware-info=", "profile=",
 			  "loglevel=",
 			  "connect", "connect-to=", "spawn-backend", "interpreter=",
-			  "mem-read=", "mem-write=", ])
+			  "mem-read=", "mem-write=",
+			  "insn-meas=", ])
 	except getopt.GetoptError as e:
 		printError(str(e))
 		usage()
@@ -586,8 +588,6 @@ def main():
 			opt_nrAccus = 4
 		if o in ("-D", "--no-cpu-dump"):
 			opt_noCpuDump = True
-		if o in ("-S", "--speed-stats"):
-			opt_speedStats = True
 		if o in ("-x", "--extended-insns"):
 			opt_extInsns = True
 		if o in ("-t", "--obtemp"):
@@ -618,6 +618,8 @@ def main():
 			except (ValueError, IndexError) as e:
 				printError("-O|--optimizers: Invalid optimization mode")
 				sys.exit(1)
+		if o == "--insn-meas":
+			opt_insnMeas = v
 		if o in ("-H", "--hardware"):
 			try:
 				v = v.split(':')

awlsim/core/cpu.pxd.in

@@ -11,6 +11,7 @@ from awlsim.core.blocks cimport *
 from awlsim.core.datablocks cimport *
 from awlsim.core.timers cimport *
 from awlsim.core.counters cimport *
+from awlsim.core.insnmeas cimport *
 
 
 cdef class S7CPU(object):
@@ -95,6 +96,7 @@ cdef class S7CPU(object):
 	cdef public MovingAvg __timestampUpdMovAvg
 	cdef public double __timestampUpdInter
 	cdef public uint32_t __timestampUpdInterMask
+	cdef public InsnMeas __insnMeas
 
 	cdef void setMcrActive(self, _Bool active)
 	cdef _Bool mcrIsOn(self)

awlsim/core/cpu.py

@@ -62,6 +62,7 @@ from awlsim.core.lstack import * #+cimport
 from awlsim.core.offset import * #+cimport
 from awlsim.core.obtemp import * #+cimport
 from awlsim.core.util import *
+from awlsim.core.insnmeas import * #+cimport
 
 from awlsim.awlcompiler.tokenizer import *
 from awlsim.awlcompiler.translator import *
@@ -513,6 +514,7 @@ class S7CPU(object): #+cdef
 		self.__callHelpers = self.__callHelpersDict		#@nocy
 		self.__rawCallHelpers = self.__rawCallHelpersDict	#@nocy
 
+		self.__insnMeas = None
 		self.__clockMemByteOffset = None
 		self.specs = S7CPUSpecs(self)
 		self.conf = S7CPUConfig(self)
@@ -792,6 +794,11 @@ class S7CPU(object): #+cdef
 
 		self.initializeTimestamp()
 
+	def setupInsnMeas(self):
+		if not self.__insnMeas:
+			self.__insnMeas = InsnMeas()
+		return self.__insnMeas
+
 	def setCycleExitCallback(self, cb, data=None):
 		self.cbCycleExit = cb
 		self.cbCycleExitData = data
@@ -839,6 +846,9 @@ class S7CPU(object): #+cdef
 #@cy		cdef LStackAllocator activeLStack
 #@cy		cdef uint32_t insnCount
 #@cy		cdef OBTempPresets presetHandler
+#@cy		cdef _Bool insnMeasEnabled
+#@cy		cdef _Bool postInsnCbEnabled
+#@cy		cdef _Bool blockExitCbEnabled
 
 		# Note: Bounds checking of the indexing operator [] is disabled
 		#       by @cython.boundscheck(False) in this method.
@@ -871,17 +881,30 @@ class S7CPU(object): #+cdef
 			presetHandler = self.obTempPresetHandlers[block.index]
 			presetHandler.generate(activeLStack.memory.getRawDataBytes())
 
+		insnMeasEnabled = self.__insnMeas is not None
+		postInsnCbEnabled = self.cbPostInsn is not None
+		blockExitCbEnabled = self.cbBlockExit is not None
+
 		# Run the user program cycle
 		while cse is not None:
 			while cse.ip < cse.nrInsns:
-				# Fetch the next instruction and run it.
-				insn, self.relativeJump = cse.insns[cse.ip], 1
-				insn.run()
-				if self.cbPostInsn is not None:
+				# Fetch the next instruction.
+				insn = cse.insns[cse.ip]
+				self.relativeJump = 1
+
+				# Execute the instruction.
+				if insnMeasEnabled: #+unlikely
+					self.__insnMeas.meas(True, insn.insnType)
+					insn.run()
+					self.__insnMeas.meas(False, insn.insnType)
+				else:
+					insn.run()
+				if postInsnCbEnabled: #+unlikely
 					self.cbPostInsn(cse, self.cbPostInsnData)
+
 				cse.ip += self.relativeJump
 				cse = self.callStackTop
-				self.__insnCount = insnCount = (self.__insnCount + 1) & 0x3FFFFFFF
+				self.__insnCount = insnCount = (self.__insnCount + 1) & 0x3FFFFFFF #+suffix-u
 
 				# Check if a timekeeping update is required.
 				if not (insnCount & self.__timestampUpdInterMask):
@@ -895,7 +918,7 @@ class S7CPU(object): #+cdef
 					if self.__runtimeLimit >= 0.0:
 						self.__checkRunTimeLimit()
 
-			if self.cbBlockExit is not None:
+			if blockExitCbEnabled: #+unlikely
 				self.cbBlockExit(self.cbBlockExitData)
 			cse, exitCse = cse.prevCse, cse
 			self.callStackTop = cse

awlsim/core/insnmeas.pxd.in

@@ -0,0 +1,18 @@
+from awlsim.common.cython_support cimport *
+from awlsim.core.instructions.main cimport *
+
+
+cdef class InsnMeasData(object):
+	cdef public _Bool running
+	cdef public _Bool measured
+	cdef public double measStart
+	cdef public double cumRt
+	cdef public uint32_t count
+	cdef public double minRt
+	cdef public double maxRt
+
+cdef class InsnMeas(object):
+	cdef public object __perf_counter
+	cdef public list __data
+
+	cdef void meas(self, _Bool begin, uint32_t insnType)

awlsim/core/insnmeas.py

@@ -0,0 +1,152 @@
+# -*- coding: utf-8 -*-
+#
+# AWL simulator - Instruction timing measurement
+#
+# Copyright 2019 Michael Buesch <m@bues.ch>
+#
+# 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, write to the Free Software Foundation, Inc.,
+# 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+#
+
+from __future__ import division, absolute_import, print_function, unicode_literals
+#from awlsim.common.cython_support cimport * #@cy
+from awlsim.common.compat import *
+
+from awlsim.common.util import *
+from awlsim.common.exceptions import *
+from awlsim.common.monotonic import * #+cimport
+
+#from awlsim.core.insnmeas cimport * #@cy
+from awlsim.core.instructions.main import * #+cimport
+from awlsim.core.instructions.types import * #+cimport
+
+import time
+
+
+__all__ = [
+	"InsnMeas",
+]
+
+
+class InsnMeasData(object): #+cdef
+	def __init__(self):
+		self.measured = False
+		self.measStart = 0.0
+		self.cumRt = 0.0
+		self.count = 0
+		self.minRt = 9999.0
+		self.maxRt = 0.0
+
+	@property
+	def avgRt(self):
+		if self.count == 0:
+			return 9999.0
+		return self.cumRt / float(self.count)
+
+	def subtractCal(self, calOffset):
+		new = InsnMeasData()
+		new.minRt = max(1.0e-9, self.minRt - calOffset)
+		new.maxRt = max(1.0e-9, self.maxRt - calOffset)
+		new.cumRt = max(1.0e-9, self.avgRt - calOffset)
+		new.count = 1
+		return new
+
+	def dump(self, name):
+		name += " " * (6 - len(name))
+		return "%s:  min: %.3f us, max: %.3f us, avg: %.3f us" % (
+			name,
+			self.minRt * 1.0e6,
+			self.maxRt * 1.0e6,
+			self.avgRt * 1.0e6)
+
+class InsnMeas(object): #+cdef
+	def __init__(self):
+		self.__perf_counter = time.perf_counter
+
+		self.__data = [None] * (AwlInsnTypes.NR_TYPES + 1)
+		for i in range(AwlInsnTypes.NR_TYPES + 1):
+			self.__data[i] = InsnMeasData()
+
+		printInfo("Running instruction measurement offset calibration...")
+		for i in range(2000000):
+			self.meas(True, AwlInsnTypes.NR_TYPES)
+			self.meas(False, AwlInsnTypes.NR_TYPES)
+		measData = self.__data[AwlInsnTypes.NR_TYPES]
+		printInfo("Instruction measurement cal offset = %f us" % (
+			  measData.avgRt * 1000000.0))
+
+	def meas(self, begin, insnType): #@nocy
+#@cy	cdef void meas(self, _Bool begin, uint32_t insnType):
+#@cy		cdef InsnMeasData measData
+#@cy		cdef double rt
+#@cy		cdef double now
+
+		now = self.__perf_counter()
+		measData = self.__data[insnType]
+		if begin:
+			measData.measStart = now
+		else:
+			rt = now - measData.measStart
+			measData.cumRt += rt
+			measData.count += 1
+			measData.minRt = min(measData.minRt, rt)
+			measData.maxRt = max(measData.maxRt, rt)
+			measData.measured = True
+
+	@property
+	def haveAnyMeasurements(self):
+		return any(self.__data[i].measured
+			   for i in range(AwlInsnTypes.NR_TYPES))
+
+	@property
+	def __calOffset(self):
+		cal = self.__data[AwlInsnTypes.NR_TYPES]
+		calOffset = cal.avgRt
+		return calOffset
+
+	@property
+	def __allMeasData(self):
+		calOffset = self.__calOffset
+		for insnType in range(AwlInsnTypes.NR_TYPES):
+			measData = self.__data[insnType]
+			if measData.measured:
+				measData = measData.subtractCal(calOffset)
+				yield insnType, measData
+
+	def dump(self):
+		if not self.haveAnyMeasurements:
+			return
+		printInfo("")
+		printInfo("Instruction time measurements:")
+		for insnType, measData in self.__allMeasData:
+			name = AwlInsnTypes.type2name_german[insnType]
+			printInfo(measData.dump(name))
+
+	def dumpCSV(self):
+		if not self.haveAnyMeasurements:
+			return ""
+		ret = [ "instruction type;"
+			"instruction name;"
+			"minimum runtime (µs);"
+			"maximum runtime (µs);"
+			"average runtime (µs)" ]
+		for insnType, measData in self.__allMeasData:
+			name = AwlInsnTypes.type2name_german[insnType]
+			ret.append("%d; %s;%.3f;%.3f;%.3f" % (
+				insnType,
+				AwlInsnTypes.type2name_german[insnType],
+				measData.minRt * 1.0e6,
+				measData.maxRt * 1.0e6,
+				measData.avgRt * 1.0e6))
+		return "\n".join(ret)

awlsim/core/instructions/types.pxd.in

@@ -170,6 +170,8 @@ cdef class __AwlInsnTypesClass(object):
 	cdef public uint32_t TYPE_GENERIC_CALL
 	cdef public uint32_t TYPE_INLINE_AWL
 
+	cdef public uint32_t NR_TYPES
+
 	cdef public dict name2type_german
 	cdef public dict name2type_english
 	cdef public dict type2name_german

awlsim/core/instructions/types.py

@@ -2,7 +2,7 @@
 #
 # AWL simulator - Instruction types
 #
-# Copyright 2012-2017 Michael Buesch <m@bues.ch>
+# Copyright 2012-2019 Michael Buesch <m@bues.ch>
 #
 # 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
@@ -205,6 +205,8 @@ class __AwlInsnTypesClass(object): #+cdef
 		# Special instructions for internal usage
 		self.TYPE_GENERIC_CALL	= EnumGen.item	# No mnemonic
 		self.TYPE_INLINE_AWL	= EnumGen.item	# No mnemonic
+		# Last element: Number of instruction types
+		self.NR_TYPES		= EnumGen.item
 		EnumGen.end
 
 		self.name2type_german = {

awlsim/core/operators.py

@@ -244,7 +244,8 @@ class AwlOperator(object): #+cdef
 						"must be only one single character "
 						"long.")
 			else:
-				if self.isImmediate():
+				if (self.isImmediate() and
+				    self.operType != AwlOperatorTypes.IMM):
 					raise AwlSimError("Invalid immediate '%s'"
 						"for CHAR data type." %\
 						str(self))