Previous Thread
Next Thread
Print Thread
Page 1 of 2 1 2
#111011 - 10/09/17 09:46 PM Compile stats  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
So it's fun to know how long and how many resources a compile takes:

I'm using ubuntu 17.04.

you can use the shell's built in time command

time make -j4

and that will put out something like:

time make -j4
GCC 6.3.0 detected
Compiling src/emu/natkeyboard.cpp...
Archiving libemu.a...
Linking mame64...

real 0m20.428s
user 0m18.012s
sys 0m2.448s

but how much memory does it take?

let's use /usr/bin/time

/usr/bin/time make -j4
GCC 6.3.0 detected
Compiling src/emu/natkeyboard.cpp...
Archiving libemu.a...
Linking mame64...
18.06user 2.48system 0:27.43elapsed 74%CPU (0avgtext+0avgdata 1705048maxresident)k
104176inputs+560208outputs (1146major+1002703minor)pagefaults 0swaps

and if you want a verbose output use

/usr/bin/time --verbose make -j4

and for a full make of mame 0190 on a Intel Core i3-3220 CPU @ 3.30GHz × 4 takes about 55 minutes.

/usr/bin/time --verbose make -j4
GCC 6.3.0 detected
...
Compiling src/mame/mame.cpp...
Compiling generated/version.cpp...
Building driver list...
34618 driver(s) found
Compiling generated/mame/mame/drivlist.cpp...
Linking mame64...
Command being timed: "make -j4"
User time (seconds): 11907.65
System time (seconds): 557.14
Percent of CPU this job got: 376%
Elapsed (wall clock) time (h:mm:ss or m:ss): 55:08.90
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 2241060
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 1547
Minor (reclaiming a frame) page faults: 221300921
Voluntary context switches: 385912
Involuntary context switches: 1218757
Swaps: 0
File system inputs: 472136
File system outputs: 5079616
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

#111012 - 10/10/17 01:40 AM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2004
Posts: 1,906
Vas Crabb Online content
Very Senior Member
Vas Crabb  Online Content
Very Senior Member

Joined: Feb 2004
Posts: 1,906
Sydney, Australia
luaengine.cpp is the killer - why not profile that? wink

#111021 - 10/10/17 01:00 PM Re: Compile stats [Re: Vas Crabb]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
How do I profile luaengine.cpp?



full compile latest git pull on an Intel Core i5 CPU 750 @ 2.67GHz x 4 cores takes 43 minutes

make clean
/usr/bin/time --verbose make -j4
GCC 6.3.0 detected
...
Building driver list...
34621 driver(s) found
Compiling generated/mame/mame/drivlist.cpp...
Linking mame64...
Command being timed: "make -j4"
User time (seconds): 8749.88
System time (seconds): 509.38
Percent of CPU this job got: 358%
Elapsed (wall clock) time (h:mm:ss or m:ss): 42:59.68
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 2235824
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 7201
Minor (reclaiming a frame) page faults: 221822793
Voluntary context switches: 401964
Involuntary context switches: 1496542
Swaps: 0
File system inputs: 1993784
File system outputs: 5175168
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 30
model name : Intel(R) Core(TM) i5 CPU 750 @ 2.67GHz
stepping : 5
microcode : 0x7
cpu MHz : 2799.000
cache size : 8192 KB
physical id : 0
siblings : 4
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm sse4_1 sse4_2 popcnt lahf_lm tpr_shadow vnmi flexpriority ept vpid dtherm ida
bugs :
bogomips : 5320.30
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:

#111225 - 11/03/17 12:37 AM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
For fun, I dug out my old Toshiba Laptop with a 32 bit processor to see how mame would do a full compile with Ubuntu 16.04 LTS.

Genuine Intel® CPU U2500 @ 1.20GHz × 2
32 bit
2.0 GiB
Ubuntu 16.04 LTS
compiling mame191

I fell asleep waiting and the computer went to sleep due to inactivity, but it said about 5 hours of elapsed time. I would guess somewhere around 3 hours since 21997 cpu seconds/ 2 cores/ 3600 seconds per hour = 3.05 hours.

Code
/usr/bin/time make -j3
GCC 5.4.0 detected
...
Compiling src/mame/mame.cpp...
Compiling generated/version.cpp...
Building driver list...
34653 driver(s) found
Compiling generated/mame/mame/drivlist.cpp...
Linking mame...
21997.50user 1333.74system 5:04:54elapsed 127%CPU (0avgtext+0avgdata 1276864maxresident)k
3508360inputs+4227088outputs (8822major+151301401minor)pagefaults 0swaps



My cool discovery of the day is the -verbose option where it will tell you all about the compiler settings used to build mame.
Code
./mame pacman -rompath ../../mameroms/ -video opengl -verbose
Available videodrivers: x11 mir wayland dummy 
Current Videodriver: x11
	Display #0
		Renderdrivers:
			    opengl (0x0)
			 opengles2 (0x0)
			  software (0x0)
Available audio drivers: 
	pulseaudio          
	alsa                
	sndio               
	dsp                 
	disk                
	dummy               
Build version:      0.191 (unknown)
Build architecure:  
Build defines 1:    SDLMAME_UNIX=1 SDLMAME_X11=1 SDLMAME_LINUX=1 
Build defines 1:    LSB_FIRST=1 
SDL/OpenGL defines: SDL_COMPILEDVERSION=2004 USE_OPENGL=1 
Compiler defines A: __GNUC__=5 __GNUC_MINOR__=4 __GNUC_PATCHLEVEL__=0 __VERSION__="5.4.0 20160609" 
Compiler defines B: __unix__=1 __i386__=1 
Compiler defines C: __USE_FORTIFY_LEVEL=0 
Enter init_monitors
Adding monitor screen0 (1280 x 800)
Leave init_monitors
Enter sdlwindow_init
Using SDL multi-window OpenGL driver (SDL 2.0+)
... <snip>

GL texture: copy 1, shader 0, dynamic 1, 288x224 288x224 [PALETTE16, Equal: 0, Palette: 1,
            scale 1x1, border 0, pitch 384,288/2048], bytes/pix 4
GL texture: copy 1, shader 0, dynamic 1, 288x224 288x224 [PALETTE16, Equal: 0, Palette: 1,
            scale 1x1, border 0, pitch 384,288/2048], bytes/pix 4
Average speed: 100.00% (7 seconds)
sdl_kill: closing audio
Enter sdlwindow_exit
Leave sdlwindow_exit

#111344 - 11/23/17 05:18 PM Re: Compile stats [Re: Vas Crabb]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
Originally Posted by Vas Crabb
luaengine.cpp is the killer - why not profile that? wink


Ok, if I make any change to luaengine.cpp (even just typing a space character) or enabling SOL_CHECK_ARGUMENTS for example:

Code
#define SOL_CHECK_ARGUMENTS
#include "sol2/sol.hpp"

Let's see how long it takes to re-compile and link,
Code
time make -j5
GCC 7 detected
Compiling src/frontend/mame/luaengine.cpp...
Compiling src/frontend/mame/clifront.cpp...
Compiling src/frontend/mame/mame.cpp...
Compiling src/frontend/mame/ui/datmenu.cpp...
Compiling src/frontend/mame/ui/mainmenu.cpp...
Compiling src/frontend/mame/ui/pluginopt.cpp...
Compiling src/frontend/mame/ui/selgame.cpp...
Compiling src/frontend/mame/ui/selmenu.cpp...
Compiling src/frontend/mame/ui/selsoft.cpp...
Compiling src/frontend/mame/ui/ui.cpp...
Archiving libfrontend.a...
Linking mame64...

real	2m2.940s
user	2m21.165s
sys	0m6.695s


Code
cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 58
model name	: Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz
stepping	: 9
microcode	: 0x1c
cpu MHz		: 3292.334

#112227 - 01/19/18 02:25 AM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
I got an i7-2600 system and thought I'd give it a go compiling mame 193. It only took 29 minutes... whee!

Code
~/Downloads/mame193_extract/mame$ /usr/bin/time make -j8
GCC 7 detected
...
34845 driver(s) found
Compiling generated/mame/mame/drivlist.cpp...
Linking mame64...
11973.80user 662.42system 29:32.70elapsed 712%CPU (0avgtext+0avgdata 2337696maxresident)k
2545752inputs+5575944outputs (12333major+234574396minor)pagefaults 0swaps

~/Downloads/mame193_extract/mame$ lscpu

Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              8
On-line CPU(s) list: 0-7
Thread(s) per core:  2
Core(s) per socket:  4
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               42
Model name:          Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz
Stepping:            7
CPU MHz:             3392.293
CPU max MHz:         3800.0000
CPU min MHz:         1600.0000
BogoMIPS:            6784.58
Virtualization:      VT-x
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            8192K
NUMA node0 CPU(s):   0-7
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm epb pti tpr_shadow vnmi flexpriority ept vpid xsaveopt dtherm ida arat pln pts

#112233 - 01/19/18 01:46 PM Re: Compile stats [Re: Golden Child]  
Joined: Mar 2001
Posts: 15,851
R. Belmont Online content
R. Belmont  Online Content

Very Senior Member

Joined: Mar 2001
Posts: 15,851
USA
Golden Child: I thought you'd find this interesting:

https://www.ebay.com/itm/VDP-1000-board-for-CP-M-Turbo-7-Run-SG-1000-Some-Colecovision-games-on-APPLE-II/282518811724?_trkparms=aid%3D222007%26algo%3DSIM.MBE%26ao%3D2%26asc%3D47300%26meid%3Db377bd165ced41c2b2404240b204bb3b%26pid%3D100623%26rk%3D3%26rkt%3D6%26sd%3D282645562451&_trksid=p2047675.c100623.m-1

It's an daughtercard for a specific (modern) Apple II Z80 board that adds the TMS9928 VDP and SN76489A sound chip at the right Z80 I/O ports so you can run unmodified SG-1000 and some Colecovision games. Genius idea, I'll emulate it in MAME soon smile

#112282 - 01/23/18 01:22 AM Re: Compile stats [Re: R. Belmont]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
Hey RB,

Oh yeah! That's really cool. Can't wait!



If it helps, I came across a manual for the VDP-1000.

http://quick09.tistory.com/attachment/cfile9.uf@245A6F405957414B121465.pdf

and he's got some posts on his website:


http://quick09.tistory.com/category/%E2%97%86%20My%20Z80%20Card


The fusion of Apple and MSX. I wonder why MS never did an add-in MSX card for the apple II.

Ian Kim's also got an ApMSX card that he's working on.






And check this prototype out: A dual ti9929 video card!

[Linked Image]

http://a2central.com/category/its-a-hack/
http://a2central.com/7211/another-p...ice-monupet-ti-d-vdp9929a-graphics-card/

#112286 - 01/23/18 10:55 AM Re: Compile stats [Re: Golden Child]  
Joined: Jul 2007
Posts: 195
Monotremata Offline
Senior Member
Monotremata  Offline
Senior Member

Joined: Jul 2007
Posts: 195
California
Hah "Man The Goonies sucks, Im gonna go play Ultima 4." Is the MSX the expansion card thats too big for the case? Whats the Apple doing just power?

#112289 - 01/23/18 12:58 PM Re: Compile stats [Re: Golden Child]  
Joined: Mar 2001
Posts: 15,851
R. Belmont Online content
R. Belmont  Online Content

Very Senior Member

Joined: Mar 2001
Posts: 15,851
USA
The Apple also uploads the Z80 code to run and provides the keyboard.

#112303 - 01/23/18 10:25 PM Re: Compile stats [Re: Golden Child]  
Joined: Jul 2007
Posts: 195
Monotremata Offline
Senior Member
Monotremata  Offline
Senior Member

Joined: Jul 2007
Posts: 195
California
Ahh gotcha! Other than running Ultima its hard to tell whats he's doing on the Apple before firing it up.

#112495 - 02/05/18 11:59 AM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
Some more silly compiling fun...

I am so enamored with lua that I thought, why not install ubuntu's lua so I can write lua scripts outside of mame.

After a "sudo apt-get install lua5.3" I can run a lua interpreter from a regular bash shell.

One of the things I like is to see what the progress is for a compile.

So why don't we pipe the output from a make to a lua script and add the seconds for fun:

This is a really simple one liner. We just get the current time and then read a line, and check the time.

Then we print the time since the compile started and then the line that was read.

Let's call it "lua_time.lua"
Code
l = os.time() while true do j = io.read() k = os.time() if j == nil then break else print(k-l, j) end end


You can try this code in the lua interpreter by launching the interpreter with "lua5.3" and then pasting the line.

Type a few test lines to see what happens.

Code
lua5.3
Lua 5.3.3  Copyright (C) 1994-2016 Lua.org, PUC-Rio
> l = os.time() while true do j = io.read() k = os.time() if j == nil then break else print(k-l, j) end end
hey
3	hey
this
5	this
works
9	works
> 


I press CTRL+D to signal the end of input and the while loop drops out since it reads nil.

Another CTRL+D will drop out of the lua interpreter.

Ok, so now we've seen that our one liner works. So let's see it in action:

Our command will be: "make -j4 | lua5.3 lua_time.lua | tee luatimemake.txt"


Code
~/Downloads/mame194_extract/mame$ make clean
GCC 7 detected
Cleaning genie
Cleaning...
make[1]: Entering directory '/home/customer/Downloads/mame194_extract/mame/src/devices/cpu/m68000'
Cleaning...
make[1]: Leaving directory '/home/customer/Downloads/mame194_extract/mame/src/devices/cpu/m68000'


~/Downloads/mame194_extract/mame$ make -j4 | lua5.3 lua_time.lua | tee luatimemake2.txt
0	GCC 7 detected
0	Creating obj/Release
0	Creating obj/Release/src/host
0	Creating obj/Release/src/host/lua-5.3.0/src
0	lapi.c
1	lauxlib.c
1	lbaselib.c
1	Converting src/mame/drivers/ymmu100.ppm...
2	make[1]: Entering directory '/home/customer/Downloads/mame194_extract/mame/src/devices/cpu/m68000'
4	lbitlib.c
4	lcode.c
4	lcorolib.c
4	Linking m68kmake...
5	lctype.c
5	ldblib.c
...etc


So after a run, we've got a file that has a log of the compile run with a time at the beginning of each line.

Let's write a little routine that opens that file, and reads it into a table where the keys are each line of the compiler output and the value is a table with two entries, the line number of the output and the time since the beginning of the compile:

Let's call this file: "lua_checktime_simple.lua".

We just match the line with the pattern (.+)\t(.+) which gets us two items separated by a tab character, and these get returned as a table since we wrap it in braces {}. We read a line into g, then set h = {"g:match("(.+)\t(.+)")}. h[1] will be the time, h[2] will be the compiler output line.

Then we make a new table using the compiler output line as the key with t[h[2]] = {}.

t[h[2]][1] = linenum sets the first entry to the current line number
t[h[2]][2] = h[1] sets the second entry to the time that we got from the match.

Code
function formattime(a) local min,sec = math.modf(a/60) return min..":"..string.format("%02.0f",sec*60) end

f = io.open("luatimemake.txt","rb")

linenum = 0
t = {} f:seek("set") g = f:read() while g ~= nil do h = {g:match("(.+)\t(.+)")} maxval = tonumber(h[1]) linenum = linenum + 1 if h[2] ~= nil then t[h[2]]={} t[h[2]][1]=linenum t[h[2]][2]=tonumber(h[1]) end g = f:read() end

itemcount = 0
for a,b in pairs(t) do itemcount = itemcount + 1 end
print("TOTAL ITEMS:" .. itemcount)

newcount = 0


starttime = os.time()


while true do

newline = io.read()
newcount = newcount + 1
if newline == nil then break end
newlinetime = os.time() - starttime
if t[newline] ~= nil then oldlinetime = t[newline][2] else oldlinetime = nil end

print (newline)

if oldlinetime == nil then print("*** line not found *** NEW >>> "..newline) else print("OLDTIME = " .. formattime(oldlinetime).." "..oldlinetime .. " NEWTIME = " .. formattime(newlinetime).." ".. newlinetime .. " COMPARISON = " .. string.format("%2.1f",(oldlinetime / newlinetime)*100) .."% ".. " ITEMCOUNT = " .. newcount .."/"..itemcount) end
end


And if we invoke this with: "make -j4 | lua5.3 lua_checktime_simple.lua"

Code
~/Downloads/mame194_extract/mame$ make -j4 | lua5.3 lua_checktime_simple.lua 
TOTAL ITEMS:8514
GCC 7 detected
OLDTIME = 0:00 0 NEWTIME = 0:00 0 COMPARISON = -nan%  ITEMCOUNT = 1/8514
Creating obj/Release
OLDTIME = 0:00 0 NEWTIME = 0:00 0 COMPARISON = -nan%  ITEMCOUNT = 2/8514
Creating obj/Release/src/host
OLDTIME = 0:00 0 NEWTIME = 0:00 0 COMPARISON = -nan%  ITEMCOUNT = 3/8514
Creating obj/Release/src/host/lua-5.3.0/src
OLDTIME = 0:00 0 NEWTIME = 0:00 0 COMPARISON = -nan%  ITEMCOUNT = 4/8514
lapi.c
OLDTIME = 0:00 0 NEWTIME = 0:00 0 COMPARISON = -nan%  ITEMCOUNT = 5/8514
lauxlib.c
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 6/8514
lbitlib.c
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 7/8514
lbaselib.c
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 8/8514
Converting src/mame/drivers/ymmu100.ppm...
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 9/8514
lcode.c
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 10/8514
lcorolib.c
OLDTIME = 0:00 0 NEWTIME = 0:01 1 COMPARISON = 0.0%  ITEMCOUNT = 11/8514
lctype.c
OLDTIME = 0:01 1 NEWTIME = 0:01 1 COMPARISON = 100.0%  ITEMCOUNT = 12/8514
ldblib.c
OLDTIME = 0:01 1 NEWTIME = 0:01 1 COMPARISON = 100.0%  ITEMCOUNT = 13/8514
ldebug.c
OLDTIME = 0:01 1 NEWTIME = 0:01 1 COMPARISON = 100.0%  ITEMCOUNT = 14/8514



Now I can load this baseline compiler log on another system and compare the cpu speed.

Just some silly fun...

#112579 - 02/11/18 05:57 PM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
I wanted a progress bar when I compile so I added that, along with a "dog bark" to tell me when it's done:

Once you've made a reference file in "luatimemake.txt" you get a nice progress bar.

make -j4 | lua5.3 compile_progress.lua


Code
-- compile_progress.lua


function dogbark() for i = 1,5 do os.execute("play -q /usr/share/sounds/gnome/default/alerts/bark.ogg") end end
-- for dogbark to work you have to "sudo apt install sox"
dogbark()

function formattime(a) local min,sec = math.modf(a/60) return min..":"..string.format("%02.0f",sec*60) end

f = io.open("luatimemake.txt","rb")
fileout = io.open("luacompareoutput.txt","w")

function progressbar(size,fraction)
local numbars = math.floor((size-2)*(fraction))
local fracpart = ((size-2)*fraction)-numbars
--local onechar = string.sub("01234567890",math.floor(fracpart*10)+1,math.floor(fracpart*10)+1)
--local onechar = string.sub(".,;:-=+\\|/*#",math.floor(fracpart*10)+1,math.floor(fracpart*10)+1)
  local onechar = string.sub(".abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ",math.floor(fracpart*53)+1,math.floor(fracpart*53)+1)
local numremain = (size-2)-numbars
if numbars >= size - 2 then onechar = "" end
  return "["..string.rep("#",numbars)..onechar..string.rep(".",numremain-string.len(onechar)).."]".." "..string.format("%6.2f%%",100*fraction) --..fracpart..numbars
end

-- for i =0,100,0.5 do print (i,progressbar(80,i/100),progressbar(10,i/100)) end

function pprint(a) fileout:write(a .. "\n") print(a) end
function printt(t) for a,b in pairs(t) do print (a,b) end end

function dumpstring(a) for k = 1,string.len(a) do print (k,string.format("%3d",string.byte(a,k)).." "..string.sub(a,k,k)) end end

function add_to_table_and_check_duplicate(linestr,timeval,t,linenum)
local linestr2
if linestr ~= nil then
-- print(linestr) 
  if t[linestr]~= nil then 
    t[linestr]["count"] = t[linestr]["count"]+1  
    linestr2 = linestr .. "<DUPLICATE LINE NUM=" .. t[linestr]["count"]..">" print(linestr) 
  end
  if t[linestr]==nil then t[linestr] ={linenum=linenum,timeval=tonumber(timeval),count=1 }
                     else t[linestr2]={linenum=linenum,timeval=tonumber(timeval),count=1 }
                        pprint ("Original at "..t[linestr]["linenum"].." Duplicate at "..linenum..":\""..linestr2.."\" origtime = "..t[linestr]["timeval"].." newtime = "..timeval) 
  end 
end 
if linestr2 ~= nil then return linestr2 else return linestr end
end

linenum = 0

arun_table = {} f:seek("set") g = f:read() 
while g ~= nil do 
timeval,linestr = g:match("(.-)\t(.*)") 

maxval = tonumber(timeval) 
linenum = linenum + 1 

add_to_table_and_check_duplicate(linestr,timeval,arun_table,linenum)

g = f:read() end

aitemcount = 0
for a,b in pairs(arun_table) do aitemcount = aitemcount + 1 end
print("TOTAL ITEMS:" .. aitemcount)

newcount = 0

brun_table = {}

starttime = os.time()

while true do

newline = io.read()
newcount = newcount + 1
if newline == nil then break end

if newline:match("\t") ~= nil then
  newlinetime,newline = newline:match("(.-)\t(.*)") 
else
  newlinetime = os.time() - starttime
end

newline = add_to_table_and_check_duplicate(newline,newlinetime,brun_table,newcount)

if arun_table[newline] ~= nil then oldlinetime = arun_table[newline]["timeval"] oldlinenum = arun_table[newline]["linenum"] else oldlinetime = nil end

pprint (newline)

if oldlinetime == nil then pprint("*** line not found *** NEW >>> "..newline) print(arun_table[newline]) else pprint("REF TIME A = " .. formattime(oldlinetime).." "..string.format("%4d",oldlinetime) .. " TIME B = " .. formattime(newlinetime).." ".. string.format("%4d",newlinetime) .. " SPEED = " .. string.format("%2.1f",(oldlinetime / newlinetime)*100) .."%".. " BCOUNT = " .. string.format("%4d",newcount) .."/"..string.format("%4d",aitemcount).." ".."ALINE = " .. string.format("%4d",oldlinenum) .."/"..string.format("%4d",aitemcount).." ".. progressbar(52,oldlinenum/aitemcount)) 
   brun_table[newline]["match"]=1
   arun_table[newline]["match"]=1
end
end

print("NOMATCH IN A")
for c,d in pairs(arun_table) do if arun_table[c]["match"]==nil then print ("NOMATCH A:"..c) end end
print("NOMATCH IN B")
for c,d in pairs(brun_table) do if brun_table[c]["match"]==nil then print ("NOMATCH B:"..c) end end

print("DUPLICATES IN A")
for c,d in pairs(arun_table) do if arun_table[c]["count"]>1 then print (arun_table[c]["count"].."x:".."\""..c.."\"") end end
print("DUPLICATES IN B")
for c,d in pairs(brun_table) do if brun_table[c]["count"]>1 then print (brun_table[c]["count"].."x:".."\""..c.."\"") end end

dogbark()


and the output looks like:

Code

GCC 7 detected
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    2/8528 ALINE =    1/8528 [..................................................]   0.01%
Creating obj/Release
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    3/8528 ALINE =    2/8528 [..................................................]   0.02%
Creating obj/Release/src/host
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    4/8528 ALINE =    3/8528 [..................................................]   0.04%
Creating obj/Release/src/host/lua-5.3.0/src
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    5/8528 ALINE =    4/8528 [a.................................................]   0.05%
lapi.c
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    6/8528 ALINE =    5/8528 [a.................................................]   0.06%
lauxlib.c
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    7/8528 ALINE =    6/8528 [a.................................................]   0.07%
lbaselib.c
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    8/8528 ALINE =    7/8528 [b.................................................]   0.08%
lbitlib.c
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =    9/8528 ALINE =    8/8528 [b.................................................]   0.09%
Converting src/mame/drivers/ymmu100.ppm...
REF TIME A = 0:00    0 TIME B = 0:00    0 SPEED = -nan% BCOUNT =   10/8528 ALINE =    9/8528 [b.................................................]   0.11%
lcode.c

...

Compiling src/mame/mame.cpp...
REF TIME A = 69:59 4199 TIME B = 41:05 2465 SPEED = 170.3% BCOUNT = 8524/8528 ALINE = 8525/8528 [#################################################Z]  99.96%
Compiling generated/version.cpp...
REF TIME A = 69:59 4199 TIME B = 41:05 2465 SPEED = 170.3% BCOUNT = 8525/8528 ALINE = 8524/8528 [#################################################Y]  99.95%
Building driver list...
REF TIME A = 69:59 4199 TIME B = 41:05 2465 SPEED = 170.3% BCOUNT = 8526/8528 ALINE = 8526/8528 [#################################################Z]  99.98%
Compiling generated/mame/mame/drivlist.cpp...
REF TIME A = 70:00 4200 TIME B = 41:05 2465 SPEED = 170.4% BCOUNT = 8527/8528 ALINE = 8527/8528 [#################################################Z]  99.99%
Linking mame64...
REF TIME A = 70:04 4204 TIME B = 41:09 2469 SPEED = 170.3% BCOUNT = 8528/8528 ALINE = 8528/8528 [##################################################] 100.00%
NOMATCH IN A
NOMATCH A:Creating ../../../../linux_gcc/bin/x64/Release/mame_mame<DUPLICATE LINE NUM=3>
NOMATCH IN B
DUPLICATES IN A
2x:"Generating m6509 disassembler source file..."
2x:""
2x:"Generating deco16 disassembler source file..."
2x:"Generating m65ce02 disassembler source file..."
2x:"Generating n2a03 disassembler source file..."
2x:"Generating m6510 disassembler source file..."
2x:"Generating r65c02 disassembler source file..."
2x:"Generating m4510 disassembler source file..."
2x:"Generating m65c02 disassembler source file..."
2x:"Generating m6502 disassembler source file..."
3x:"Creating ../../../../linux_gcc/bin/x64/Release/mame_mame"
2x:"Generating m740 disassembler source file..."
DUPLICATES IN B
2x:"Generating m6509 disassembler source file..."
2x:""
2x:"Generating deco16 disassembler source file..."
2x:"Generating m65ce02 disassembler source file..."
2x:"Generating n2a03 disassembler source file..."
2x:"Generating m6510 disassembler source file..."
2x:"Generating m740 disassembler source file..."
2x:"Generating r65c02 disassembler source file..."
2x:"Generating m4510 disassembler source file..."
2x:"Generating m6502 disassembler source file..."
2x:"Creating ../../../../linux_gcc/bin/x64/Release/mame_mame"
2x:"Generating m65c02 disassembler source file..."


I couldn't figure out why the line counts didn't match sometimes I wanted to "diff" the runs to see how the were different.

For instance, the first run A has 3 lines of "Creating ../../../../linux_gcc/bin/x64/Release/mame_mame" where the second run B has only 2 line of "Creating ../../../../linux_gcc/bin/x64/Release/mame_mame".

#112689 - 02/19/18 12:29 PM Re: Compile stats [Re: Golden Child]  
Joined: Feb 2014
Posts: 127
Golden Child Offline
Senior Member
Golden Child  Offline
Senior Member

Joined: Feb 2014
Posts: 127
And more silly compiling fun (under Ubuntu 17.10)

I thought I'd add some speech so that it'd say "Compile started" and "Compile Completed". Ubuntu's got this spd-say command which makes it easy, just do an os.execute("spd-say 'Open the pod bay doors, hal'")

And I wanted to see some graphics so why not try to send some values to gnuplot using lua, like this perl script from https://www.thanassis.space/gnuplotStreaming.html

and you get something like this:

[Linked Image]

and if you make a reference timefile you can just cat it to this script (which is fun to watch because it's fast):

cat luatimemake.txt | lua5.3 luaplot_test.lua

If you haven't got gnuplot installed, just do "sudo apt install gnuplot-qt".

Code

numbarks = 1

brun_table = {}
brun_linenumkey_table = {}


function saystring(str) str = "\""..str.."\"" print(str) os.execute("spd-say -w "..str)  end


function dogbark() for i = 1,numbarks do os.execute("play -q /usr/share/sounds/gnome/default/alerts/bark.ogg") end end
-- for dogbark to work you have to "sudo apt install sox"
dogbark()
saystring("Compile started")

f = io.open("luatimemake.txt","rb")
fileout = io.open("luacompareoutput2.txt","w")
linenum = 0

function formattime(a) local min,minfrac = math.modf(a/60) return min..":"..string.format("%02.0f",minfrac*60) end

function progressbar(size,fraction)
local numbars = math.floor((size-2)*(fraction))
local fracpart = ((size-2)*fraction)-numbars
--local onechar = string.sub("01234567890",math.floor(fracpart*10)+1,math.floor(fracpart*10)+1)
--local onechar = string.sub(".,;:-=+\\|/*#",math.floor(fracpart*10)+1,math.floor(fracpart*10)+1)
  local onechar = string.sub(".abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ",math.floor(fracpart*53)+1,math.floor(fracpart*53)+1)
local numremain = (size-2)-numbars
if numbars >= size - 2 then onechar = "" end
  return "["..string.rep("#",numbars)..onechar..string.rep(".",numremain-string.len(onechar)).."]".." "..string.format("%6.2f%%",100*fraction)
end

-- for i =0,100,0.5 do print (i,progressbar(80,i/100),progressbar(10,i/100)) end

function pprint(a) fileout:write(a .. "\n") print(a) end
function printt(t) for a,b in pairs(t) do print (a,b) end end

function dumpstring(a) for k = 1,string.len(a) do print (k,string.format("%3d",string.byte(a,k)).." "..string.sub(a,k,k)) end end

function add_to_table_and_check_duplicate(linestr,linetime,run_table,linenum,linenum_key_table)
local linestr2
if linestr ~= nil then
-- print(linestr) 
  if run_table[linestr]~= nil then 
    run_table[linestr]["count"] = run_table[linestr]["count"]+1  
    linestr2 = linestr .. "<DUPLICATE LINE NUM=" .. run_table[linestr]["count"]..">" print(linestr) 
  end
  if run_table[linestr]==nil then run_table[linestr] ={linenum=linenum,linetime=tonumber(linetime),count=1 }
                     else run_table[linestr2]={linenum=linenum,linetime=tonumber(linetime),count=1 }
                        pprint ("Original at "..run_table[linestr]["linenum"].." Duplicate at "..linenum..":\""..linestr2.."\" origtime = "..run_table[linestr]["linetime"].." newtime = "..linetime) 
  end 
end 
  if linestr2 ~= nil then 
     linenum_key_table[linenum]=linestr2
     run_table[linestr2]["linestr"]=linestr2
     return linestr2 
  else 
     linenum_key_table[linenum]=linestr
     run_table[linestr]["linestr"]=linestr
     return linestr 
  end
end



arun_linenumkey_table = {}
arun_table = {} f:seek("set") g = f:read() 
while g ~= nil do 
linetime,linestr = g:match("(.-)\t(.*)") 

maxval = tonumber(linetime) 
linenum = linenum + 1 

add_to_table_and_check_duplicate(linestr,linetime,arun_table,linenum,arun_linenumkey_table)

g = f:read() end

function setup_plot() 
pip = io.popen("gnuplot ","w")
end

function setup_plot2() 
pip2 = io.popen("gnuplot ","w")
end

function iif(a,b,c) if a then return b else return c end end

function make_plot2()

pip2:write("set xlabel 'time (in seconds)'\n")
pip2:write("set ylabel 'compile items'\n")
pip2:write("set style line 2 linewidth 2\n")

pip2:write("y2(x)=m2*x+b2\n")
pip2:write("set fit quiet\n")

pip2:write("fit y2(x) '-' via m2,b2\n")

for i =1,#brun_linenumkey_table,iif(#brun_linenumkey_table<skipinterval,1,skipinterval*skipfitmultiplier) do 
pip2:write(brun_table[brun_linenumkey_table[i]]["linetime"].." "..brun_table[brun_linenumkey_table[i]]["linenum"].."\n")
end
pip2:write("e\n")
pip2:flush()

pip2:write("plot '-' title 'brun' with lines,y2(x)\n")

for i =#brun_linenumkey_table-50,#brun_linenumkey_table do 
if i>=1 then
pip2:write(brun_table[brun_linenumkey_table[i]]["linetime"].." "..brun_table[brun_linenumkey_table[i]]["linenum"].."\n")
end
end
pip2:write("e\n")
pip2:flush()

end

skipinterval = 10 -- lets skip to plot less datapoints, make it faster
skipmultiplier = 2
skipfitmultiplier = 5
function make_plot()

pip:write("set xlabel 'time (in seconds)'\n")
pip:write("set ylabel 'compile items'\n")

pip:write("y(x)=m*x+b\n")
pip:write("set fit quiet\n")
pip:write("fit y(x) '-' via m,b\n")

for i =1,#arun_linenumkey_table,skipinterval*skipfitmultiplier do 
pip:write(arun_table[arun_linenumkey_table[i]]["linetime"].." "..arun_table[arun_linenumkey_table[i]]["linenum"].."\n")
end
pip:write("e\n")
pip:flush()


pip:write("y2(x)=m2*x+b2\n")
pip:write("fit y2(x) '-' via m2,b2\n")


for i =1,#brun_linenumkey_table,skipinterval*skipfitmultiplier do 
pip:write(brun_table[brun_linenumkey_table[i]]["linetime"].." "..brun_table[brun_linenumkey_table[i]]["linenum"].."\n")
end
pip:write("e\n")
pip:flush()


pip:write("set style line 2 linewidth 2\n")
pip:write("set style line 3 linewidth 6\n")
pip:write("set yrange [*:10000]\n")
--pip:write("plot y(x), '-' with lines, '-' with points\n")
pip:write("plot y(x), '-' title 'arun' with lines, '-' title 'brun' with lines ls 3, y2(x)\n")


for i =1,#arun_linenumkey_table,skipinterval do 
pip:write(arun_table[arun_linenumkey_table[i]]["linetime"].." "..arun_table[arun_linenumkey_table[i]]["linenum"].."\n")
end
pip:write("e\n")
pip:flush()

for i =1,#brun_linenumkey_table,skipinterval do 
--print (i,brun_linenumkey_table[i],brun_table[brun_linenumkey_table[i]]["linetime"],brun_table[brun_linenumkey_table[i]]["linenum"])
pip:write(brun_table[brun_linenumkey_table[i]]["linetime"].." "..brun_table[brun_linenumkey_table[i]]["linenum"].."\n")
end
pip:write("e\n")
pip:flush()

end -- makeplot

setup_plot()
make_plot()

setup_plot2()

alinecount = 0
for a,b in pairs(arun_table) do alinecount = alinecount + 1 end
print("TOTAL ITEMS:" .. alinecount)

blinecount = 0

brun_table = {}
brun_linenumkey_table = {}

starttime = os.time()


while true do

if (blinecount % (skipinterval*skipmultiplier)) == 0 then make_plot() end

if (blinecount % 2) == 0 then make_plot2() end

newline = io.read()
blinecount = blinecount + 1



if newline == nil then break end

if string.match(newline,"(Linking mame64)") then saystring(string.match(newline,"(Linking mame64)")) end

if newline:match("\t") ~= nil then
  print("matching TAB character")
  newlinetime,newline = newline:match("(.-)\t(.*)") 
  if newlinetime=="" then print("newlinetime is empty string") newlinetime = os.time() - starttime print(newlinetime) end
  if newlinetime==nil then print("newlinetime is nil") newlinetime = os.time() - starttime print(newlinetime) end
else
  newlinetime = os.time() - starttime
end

newline = add_to_table_and_check_duplicate(newline,newlinetime,brun_table,blinecount,brun_linenumkey_table)

if arun_table[newline] ~= nil then oldlinetime = arun_table[newline]["linetime"] oldlinenum = arun_table[newline]["linenum"] else oldlinetime = nil end

pprint (newline)

if oldlinetime == nil then pprint("*** line not found *** NEW >>> "..newline) print(arun_table[newline]) else pprint("REF TIME A = " .. formattime(oldlinetime).." "..string.format("%4d",oldlinetime) .. " TIME B = " .. formattime(newlinetime).." ".. string.format("%4d",newlinetime) .. " SPEED = " .. string.format("%2.1f",(oldlinetime / newlinetime)*100) .."%".. " BCOUNT = " .. string.format("%4d",blinecount) .."/"..string.format("%4d",alinecount).." ".."ALINE = " .. string.format("%4d",oldlinenum) .."/"..string.format("%4d",alinecount).." ".. progressbar(52,oldlinenum/alinecount)) 
   brun_table[newline]["match"]=1
   arun_table[newline]["match"]=1
end
end

print("NOMATCH IN A")
for c,d in pairs(arun_table) do if arun_table[c]["match"]==nil then print ("NOMATCH A:"..c) end end
print("NOMATCH IN B")
for c,d in pairs(brun_table) do if brun_table[c]["match"]==nil then print ("NOMATCH B:"..c) end end

print("DUPLICATES IN A")
for c,d in pairs(arun_table) do if arun_table[c]["count"]>1 then print (arun_table[c]["count"].."x:".."line "..arun_table[c]["linenum"]..":".."\""..c.."\"") end end

print("DUPLICATES IN A IN ORDER")
for i =1,#arun_linenumkey_table do if arun_table[arun_linenumkey_table[i]]["count"]>1 or string.find(arun_table[arun_linenumkey_table[i]]["linestr"],"<DUPLICATE LINE NUM=") ~= nil then print("A DUP:"..arun_table[arun_linenumkey_table[i]]["count"].."x:".."line "..arun_table[arun_linenumkey_table[i]]["linenum"]..":".."\""..arun_linenumkey_table[i].."\"") end end

print("DUPLICATES IN B")
for c,d in pairs(brun_table) do if brun_table[c]["count"]>1 then print (brun_table[c]["count"].."x:".."line "..arun_table[c]["linenum"]..":".."\""..c.."\"") end end

print("DUPLICATES IN B IN ORDER")
for i =1,#brun_linenumkey_table do if brun_table[brun_linenumkey_table[i]]["count"]>1 or string.find(brun_table[brun_linenumkey_table[i]]["linestr"],"<DUPLICATE LINE NUM=") ~= nil then print("B DUP:"..brun_table[arun_linenumkey_table[i]]["count"].."x:".."line "..brun_table[brun_linenumkey_table[i]]["linenum"]..":".."\""..brun_linenumkey_table[i].."\"") end end

print("NUM ENTRIES IN A: "..#arun_linenumkey_table)
print("NUM ENTRIES IN B: "..#brun_linenumkey_table)

compilemins,compileminsfrac = math.modf((os.time()-starttime)/60)
compilesecs = compileminsfrac * 60
saystring("Compile completed in "..string.format("%.0f",compilemins).." minutes and "..string.format("%.0f",compilesecs).." seconds.")

dogbark()

os.execute("sleep 10")

pip:close()
pip2:close()


Page 1 of 2 1 2

Moderated by  R. Belmont 

Who's Online Now
5 registered members (robcfg, MarkBielman, R. Belmont, elcondor, Vas Crabb), 28 guests, and 0 spiders.
Key: Admin, Global Mod, Mod
Shout Box
Forum Statistics
Forums9
Topics8,496
Posts110,806
Members4,781
Most Online225
May 26th, 2014
Powered by UBB.threads™ PHP Forum Software 7.6.0
Page Time: 0.069s Queries: 14 (0.041s) Memory: 5.0888 MB (Peak: 5.3662 MB) Zlib enabled. Server Time: 2018-02-22 16:18:35 UTC