Topic by dan

Posted: 2/21/2018 4:56 AM

Post subject: Lua command to control the tracelogger

Quote

dan

He/Him

Joined: 9/23/2016
Posts: 25

I would like to create frame-specific trace logs for semi-automated analysis of existing TASes. My idea is to have a separate process grep for a couple things from each trace log, save that information elsewhere, and delete the frame-specific trace log. That way, I can start the Lua script, play a section of the TAS, go do something, and have results to look at when I come back. From there, I can identify frames of interest for further analysis. Some ideas include calculating the percentage of idle instructions in each frame for lag reduction, as well as identifying the multiple areas of code where the game reads the RNG variable. I read the Lua documentation and did not see a Lua method available to control the tracelogging. Would it be difficult to change lsnes-bsnes to expose this via a Lua command? In the past, I have copy-pasted the output from the tracelogger window, and cut the tracelog apart via a script. This still requires some manual effort. Having separate trace log files would require less disk space, and maybe even cause less I/O overhead too. Sample Lua script

local PROCID_CPU=0; 
function on_frame()
  -- Not valid Lua
  debug_context::tracelog(PROCID_CPU, string.format("C:\\Path\\To\\My\\Trace\\Logs\\frame-%06d.trace", movie.currentframe()));
end
on_frame_emulated()
  -- Not valid Lua
  debug_context::tracelog(PROCID_CPU, "");
end

Sample Log output

Loaded 'C:\Path\To\Someone\Elses\TAS\finished-tas.lsmv' in 549032 microseconds.
Tracelogging processor #0 to 'C:\Path\To\My\Trace\Logs\frame-000165.trace'
Stopped tracelogging processor #0
Tracelogging processor #0 to 'C:\Path\To\My\Trace\Logs\frame-000166.trace'
Stopped tracelogging processor #0
Tracelogging processor #0 to 'C:\Path\To\My\Trace\Logs\frame-000167.trace'
Stopped tracelogging processor #0
  .
  :

Thanks.

Posted: 2/21/2018 1:36 PM

Quote

Amaraticando

It/Its

Editor, Player (159)

Joined: 1/10/2012
Posts: 673
Location: Brazil

Take a look at memory.settrace(filename) If filename is non-empty, output trace to that file. If "", stop tracing. For some reason it's not in the pdf. You can also tracelog to a file with the internal command

tracelog:
    <cpuid> <file>: Start tracing <cpuid> to <file>
    <cpuid>: End tracing <cpuid>

Internal commands can be manually typed in the message window and invoked from Lua using exec(string command). I hope that helps. If not, the best place to ask is at #lsnes IRC.

Posted: 2/21/2018 11:17 PM

Quote

dan

He/Him

Joined: 9/23/2016
Posts: 25

That was incredibly helpful. Thank you. Finished script:

local FILENAME_PATTERN="C:\\ALL\\YOUR\\TRACE\\LOGS\\GO\\HERE\\%s\\frame-%06d.trace";
local DIRECTORY="TESTING"; 
-- Directory C:\ALL\YOUR\TRACE\LOGS\GO\HERE\TESTING must already exist

function on_frame()
  exec("tracelog cpu " .. string.format(FILENAME_PATTERN, DIRECTORY, movie.currentframe()));
end
function on_frame_emulated()
  exec("tracelog cpu");
end

Posted: 2/21/2018 11:22 PM

Quote

brunovalads

Editor, Player (175)

Joined: 4/7/2015
Posts: 331
Location: Porto Alegre, RS, Brazil

Btw, just an editing tip: you can make syntax highlights here, with [code=lua] your code here [/code]

Language: lua
local FILENAME_PATTERN="C:\\ALL\\YOUR\\TRACE\\LOGS\\GO\\HERE\\%s\\frame-%06d.trace"; 
local DIRECTORY="TESTING"; 
-- Directory C:\ALL\YOUR\TRACE\LOGS\GO\HERE\TESTING must already exist 

function on_frame() 
  exec("tracelog cpu " .. string.format(FILENAME_PATTERN, DIRECTORY, movie.currentframe())); 
end 
function on_frame_emulated() 
  exec("tracelog cpu"); 
end

Games are basically math with a visual representation of this math, that's why I make the scripts, to re-see games as math. My things: YouTube, GitHub, Pastebin, Twitter

Posted: 2/22/2018 1:58 PM

Quote

feos

Site Admin, Skilled player (1254)

Joined: 4/17/2010
Posts: 11475
Location: Lake Chargoggagoggmanchauggagoggchaubunagungamaugg

Or even neater, downloadable file: [code=script.lua]] your code here [/code] Download script.lua

Language: lua
local FILENAME_PATTERN="C:\\ALL\\YOUR\\TRACE\\LOGS\\GO\\HERE\\%s\\frame-%06d.trace"; 
local DIRECTORY="TESTING"; 
-- Directory C:\ALL\YOUR\TRACE\LOGS\GO\HERE\TESTING must already exist 

function on_frame() 
  exec("tracelog cpu " .. string.format(FILENAME_PATTERN, DIRECTORY, movie.currentframe())); 
end 
function on_frame_emulated() 
  exec("tracelog cpu"); 
end

Warning: When making decisions, I try to collect as much data as possible before actually deciding. I try to abstract away and see the principles behind real world events and people's opinions. I try to generalize them and turn into something clear and reusable. I hate depending on unpredictable and having to make lottery guesses. Any problem can be solved by systems thinking and acting.

Posted: 2/24/2018 3:13 AM

Quote

dan

He/Him

Joined: 9/23/2016
Posts: 25

I figured it might be more helpful if I post my final solution, complete with the processing script too. Using Git Bash on Windows, it processes ~1,000 frames per hour. Linux is probably faster, but you can kick off both scripts, start a TAS, and collect all the data hands-off. I'm sure there's a better way to sync the scripts other than testing that a file exists, but it's good enough for now. Download trace-every-frame.lua

Language: lua
local FILENAME_PATTERN="C:\\ALL\\YOUR\\TRACE\\LOGS\\GO\\HERE\\%s\\frame-%06d.trace";
local DIRECTORY="TESTING";
-- Directory C:\ALL\YOUR\TRACE\LOGS\GO\HERE\TESTING must already exist 

function file_exists(file)
  local f = io.open(file, "r")
  -- Note: If you stop this Lua script at the wrong time, you may need to close lsnes in order to delete this file.
  if f then f:close() end
  return f ~= nil
end

function on_frame()
  local fiveFrameEarlier=(movie.currentframe()-5);
  if (fiveFrameEarlier > 0)
  then 
    traceLogFile_fiveFramesEarlier=string.format(FILENAME_PATTERN, DIRECTORY, fiveFrameEarlier);
    
    local idle=file_exists(traceLogFile_fiveFramesEarlier);
    while idle
    do
      -- lsnes spits out the trace logs faster than the other script can process them
      -- if lsnes is more than 5 frames ahead of the processing script,
      -- then do nothing until the processing script catches up
      delay=123456;
      while (delay > 0)
      do
        delay=delay-1;
      end;
      idle=file_exists(traceLogFile_fiveFramesEarlier);
    end; 
  end;

  exec("tracelog cpu " .. string.format(FILENAME_PATTERN, DIRECTORY, movie.currentframe()));
end
function on_frame_emulated()
  exec("tracelog cpu");
end

Download process-trace-logs.sh

Language: shell
function processTraceLog {
  traceLogToAnalyze="$1";
  
  matchLines=$(grep '^[0-9a-f]\{6\} \(\(st\|ld\)a \$0123\|jsl $456789\)' $traceLogToAnalyze | grep -v '^\(123456\|789abc\|def012\)');
  numMatches=$(echo "$matchLines" | grep -c '.');
  echo "$traceLogToAnalyze:$numMatches";
  if [ $numMatches -gt 0 ];
  then
    echo "$matchLines" | cut -b -36 | sed 's/^/  /g';
  fi;
  
  # cannot delete current file if the Lua script is checking to see if it exists
  while [ -f $traceLogToAnalyze ];
  do
    rm 2>/dev/null $traceLogToAnalyze;
    sleep 1;
  done;
}

touch output.log;
while [ 1 -eq 1 ]; # infinite loop
do
  if [ $(ls -1 *.trace | wc -l) -gt 1 ];
  then
    # the next trace file has started, so the previous is finished
    processTraceLog $(ls -1rt *.trace | grep -v 'output.log' | head -n 1) | tee -a output.log;
  fi; 
done;

Posted: 2/24/2018 2:45 PM

Quote

Masterjun

He/Him

Site Developer, Skilled player (1987)

Joined: 10/12/2010
Posts: 1185
Location: Germany

For anyone reading this thread and wanting to have lines of trace log in the Lua itself (to avoid doing external processing, like above), use memory.registertrace and memory.unregistertrace, documented in the lua.pdf file.

Warning: Might glitch to credits I will finish this ACE soon as possible (or will I?)

Forum lsnes Lua command to control the tracelogger

dan

Amaraticando

dan

brunovalads

feos

dan

Masterjun

Forum

lsnes

Lua command to control the tracelogger