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
TAS of 2015 SNES TAS of 2015
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 (174)
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 (1250)
Joined: 4/17/2010
Posts: 11475
Location: Lake Char­gogg­a­gogg­man­chaugg­a­gogg­chau­bun­a­gung­a­maugg
NES TAS of 2011
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
Exotic platforms TAS of 2020 Speedy TAS of 2018 PC TAS of 2018 Glitchy TAS of 2015 TASer of 2014 SNES TASer of 2014 TAS of 2014 SNES TAS of 2014 Funny TAS of 2014 Glitchy TAS of 2014 TASer of 2013 SNES TASer of 2013 NES TAS of 2013 SNES TAS of 2012 Funny TAS of 2012
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?)