Common log format

Emulation of old PCs, PC hardware, or PC peripherals.

Re: Common log format

Postby superfury » 2017-10-21 @ 12:00

I've just added a simple option to use IPS(Instructions per Second) clocking instead of the cycle-accurate clock. It should make it easier to compare between the emulators, since cycle-accurate clocking will have the effect of using completely different execution paths, depending on various cycle differences? (Hardware timing, CPU timing, DMA timing etc.)

What this new option I've implemented does is the following:
- The default cycle count is changed from the cycle-accurate timing to 3000 IPS cycles(1 IPS cycles speed is 1000 instructions per second, so it's Dosbox's default speed).
- Hardware(including DMA) and realtime synchronization is timed by executed status(instruction finished executing or not). The CPU itself is unmodified and executes in it's usual cycle-accurate method internally.
- DMA doesn't take the BUS from the CPU anymore. Instead it assumes full control over the BUS always(the same applies to the CPU, since it never has control taken from it). SI(and S1) always follows S4, since the BUS is always assumed to be freed after S4 and at SI.

That way, it becomes fully IPS-compliant, allowing for a comparision without requiring cycle-accuracy(since everything is timed using instruction clocks only instead of cycle clocking, which may vary between emulators).

Your ideas on this take?
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-21 @ 22:20

I think that might work. If time only passes when you retire an instruction.

However, how do you solve the IPS given that our emulators would take longer (in actual real time) to emulate an IMUL as opposed to an XOR (should be 10x longer)? How do you have a constant IPS when exeuting instructions for which the emulation time is not constant? Remember our emulators don't simply have a big switch case with an "atomic" execution.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-22 @ 00:13

Simply a flag that indicates an intruction is finished instead of 1 cycle to spend(which during cycle accurate CPU emulation is usually a constant 1(cycle spent by the BIU)). Since it's only 1 when a instruction retires(the debugger can step/log the completed instruction in my emulator, I assume it's the same with yours?), I use that one to tick hardware 1 or 0 CPU cycles, instead of always 1 cycle. Of course using Dosbox clocks 3000 cycles means 3000000 IPS(since it's Instructions per ms).

Even though instructions take multiple cycles, instead of updating hardware each cycle, make it possible to only tick one CPU cycle worth of realtime(UniPCemu comverts the CPU cycles or IPS cycle(execution completed flag) to nanoseconds(time passed), then also converts that to 14MHz cycles for ISA devices. Either nanoseconds and/or 14MHz clock cycles is then sent to all hardware to update their internal clocks.

That ensures that the CPU can run in various clock speeds and modes(IPS vs cycles) while each hardware runs at it's own (comstant, if applicable) speed in parallel to the CPU.

Code: Select all
OPTINLINE byte coreHandler()
{
   uint_32 MHZ14passed; //14 MHZ clock passed?
   byte BIOSMenuAllowed = 1; //Are we allowed to open the BIOS menu?
   //CPU execution, needs to be before the debugger!
   lock(LOCK_INPUT);
   if (unlikely((haswindowactive&0x1C)==0xC)) {getnspassed(&CPU_timing); haswindowactive|=0x10;} //Pending to finish Soundblaster!
   currenttiming += likely(haswindowactive&2)?getnspassed(&CPU_timing):0; //Check for any time that has passed to emulate! Don't emulate when not allowed to run, keeping emulation paused!
   unlock(LOCK_INPUT);
   uint_64 currentCPUtime = (uint_64)currenttiming; //Current CPU time to update to!
   uint_64 timeoutCPUtime = currentCPUtime+TIMEOUT_TIME; //We're timed out this far in the future (1ms)!

   double instructiontime,timeexecuted=0.0f; //How much time did the instruction last?
   byte timeout = TIMEOUT_INTERVAL; //Check every 10 instructions for timeout!
   for (;last_timing<currentCPUtime;) //CPU cycle loop for as many cycles as needed to get up-to-date!
   {
      if (debugger_thread)
      {
         if (threadRunning(debugger_thread)) //Are we running the debugger?
         {
            instructiontime = currentCPUtime - last_timing; //The instruction time is the total time passed!
            updateAudio(instructiontime); //Discard the time passed!
            timeexecuted += instructiontime; //Increase CPU executed time executed this block!
            last_timing += instructiontime; //Increase the last timepoint!
            goto skipCPUtiming; //OK, but skipped!
         }
      }
      if (BIOSMenuThread)
      {
         if (threadRunning(BIOSMenuThread)) //Are we running the BIOS menu and not permanently halted? Block our execution!
         {
            if ((CPU[activeCPU].halt&2)==0) //Are we allowed to be halted entirely?
            {
               instructiontime = currentCPUtime - last_timing; //The instruction time is the total time passed!
               updateAudio(instructiontime); //Discard the time passed!
               timeexecuted += instructiontime; //Increase CPU executed time executed this block!
               last_timing += instructiontime; //Increase the last timepoint!
               goto skipCPUtiming; //OK, but skipped!
            }
            BIOSMenuAllowed = 0; //We're running the BIOS menu! Don't open it again!
         }
      }
      if ((CPU[activeCPU].halt&2)==0) //Are we running normally(not partly ran without CPU from the BIOS menu)?
      {
         BIOSMenuThread = NULL; //We don't run the BIOS menu anymore!
      }

      if (allcleared) return 0; //Abort: invalid buffer!

      interruptsaved = 0; //Reset PIC interrupt to not used!
      if (!CPU[activeCPU].registers) //We need registers at this point, but have none to use?
      {
         return 0; //Invalid registers: abort, since we're invalid!
      }

      CPU_resetTimings(); //Reset all required CPU timings required!

      CPU_tickPendingReset();

      if ((CPU[activeCPU].halt&3) && (BIU_Ready() && CPU[activeCPU].resetPending==0)) //Halted normally with no reset pending? Don't count CGA wait states!
      {
         if (romsize) //Debug HLT?
         {
            MMU_dumpmemory("bootrom.dmp"); //Dump the memory to file!
            return 0; //Stop execution!
         }

         if (FLAG_IF && PICInterrupt() && ((CPU[activeCPU].halt&2)==0)) //We have an interrupt? Clear Halt State when allowed to!
         {
            CPU[activeCPU].halt = 0; //Interrupt->Resume from HLT
            goto resumeFromHLT; //We're resuming from HLT state!
         }
         else
         {
            //Execute using actual CPU clocks!
            CPU[activeCPU].cycles = 1; //HLT takes 1 cycle for now, since it's unknown!
         }
         if (CPU[activeCPU].halt==1) //Normal halt?
         {
            //Increase the instruction counter every instruction/HLT time!
            cpudebugger = needdebugger(); //Debugging information required? Refresh in case of external activation!
            if (cpudebugger) //Debugging?
            {
               debugger_beforeCPU(); //Make sure the debugger is prepared when needed!
               debugger_setcommand("<HLT>"); //We're a HLT state, so give the HLT command!
            }
            CPU[activeCPU].executed = 1; //For making the debugger execute correctly!
            //Increase the instruction counter every cycle/HLT time!
            debugger_step(); //Step debugger if needed, even during HLT state!
         }
      }
      else //We're not halted? Execute the CPU routines!
      {
         resumeFromHLT:
         if (CPU[activeCPU].instructionfetch.CPU_isFetching && (CPU[activeCPU].instructionfetch.CPU_fetchphase==1)) //We're starting a new instruction?
         {
            if (CPU[activeCPU].registers && doEMUsinglestep && allow_debuggerstep) //Single step enabled and allowed?
            {
               if (getcpumode() == (doEMUsinglestep - 1)) //Are we the selected CPU mode?
               {
                  switch (getcpumode()) //What CPU mode are we to debug?
                  {
                  case CPU_MODE_REAL: //Real mode?
                     singlestep |= ((CPU[activeCPU].registers->CS == (((singlestepaddress >> 16)&0xFFFF)) && ((CPU[activeCPU].registers->IP == (singlestepaddress & 0xFFFF))||(singlestepaddress&0x1000000000000ULL)))||(singlestepaddress&0x2000000000000ULL)); //Single step enabled?
                     break;
                  case CPU_MODE_PROTECTED: //Protected mode?
                  case CPU_MODE_8086: //Virtual 8086 mode?
                     singlestep |= ((CPU[activeCPU].registers->CS == (((singlestepaddress >> 32)&0xFFFF)) && ((CPU[activeCPU].registers->EIP == (singlestepaddress & 0xFFFFFFFF))||(singlestepaddress&0x1000000000000ULL)))||(singlestepaddress&0x2000000000000ULL)); //Single step enabled?
                     break;
                  default: //Invalid mode?
                     break;
                  }
               }
            }

            cpudebugger = needdebugger(); //Debugging information required? Refresh in case of external activation!
            MMU_logging = debugger_logging(); //Are we logging?

            HWINT_saved = 0; //No HW interrupt by default!
            CPU_beforeexec(); //Everything before the execution!
            if ((!CPU[activeCPU].trapped) && CPU[activeCPU].registers && CPU[activeCPU].allowInterrupts && (CPU[activeCPU].permanentreset==0) && (CPU[activeCPU].internalinterruptstep==0) && BIU_Ready() && (CPU_executionphase_busy()==0)) //Only check for hardware interrupts when not trapped and allowed to execute interrupts(not permanently reset)!
            {
               if (FLAG_IF) //Interrupts available?
               {
                  if (PICInterrupt()) //We have a hardware interrupt ready?
                  {
                     HWINT_nr = nextintr(); //Get the HW interrupt nr!
                     HWINT_saved = 2; //We're executing a HW(PIC) interrupt!
                     if (!((EMULATED_CPU <= CPU_80286) && REPPending)) //Not 80386+, REP pending and segment override?
                     {
                        CPU_8086REPPending(); //Process pending REPs normally as documented!
                     }
                     else //Execute the CPU bug!
                     {
                        CPU_8086REPPending(); //Process pending REPs normally as documented!
                        CPU[activeCPU].registers->EIP = CPU_InterruptReturn; //Use the special interrupt return address to return to the last prefix instead of the start!
                     }
                     CPU_exec_lastCS = CPU_exec_CS;
                     CPU_exec_lastEIP = CPU_exec_EIP;
                     CPU_exec_CS = CPU[activeCPU].registers->CS; //Save for error handling!
                     CPU_exec_EIP = CPU[activeCPU].registers->EIP; //Save for error handling!
                     CPU_saveFaultData(); //Save fault data to go back to when exceptions occur!
                     call_hard_inthandler(HWINT_nr); //get next interrupt from the i8259, if any!
                  }
               }
            }

            #ifdef LOG_BOGUS
            uint_32 addr_start, addr_left, curaddr; //Start of the currently executing instruction in real memory! We're testing 5 instructions!
            addr_left=2*LOG_BOGUS;
            curaddr = 0;
            addr_start = CPU_MMU_start(CPU_SEGMENT_CS,CPU[activeCPU].registers->CS); //Base of the currently executing block!
            addr_start += REG_EIP; //Add the address for the address we're executing!
         
            for (;addr_left;++curaddr) //Test all addresses!
            {
               if (MMU_directrb_realaddr(addr_start+curaddr)) //Try to read the opcode! Anything found(not 0000h instruction)?
               {
                  break; //Stop searching!
               }
               --addr_left; //Tick one address checked!
            }
            if (addr_left==0) //Bogus memory detected?
            {
               dolog("bogus","Bogus exection memory detected(%u 0000h opcodes) at %04X:%08X! Previous instruction: %02X(0F:%u)@%04X:%08X",LOG_BOGUS,CPU[activeCPU].registers->CS,CPU[activeCPU].registers->EIP,CPU[activeCPU].previousopcode,CPU[activeCPU].previousopcode0F,CPU_exec_lastCS,CPU_exec_lastEIP); //Log the warning of entering bogus memory!
            }
            #endif
         }

         CPU_exec(); //Run CPU!

         //Increase the instruction counter every cycle/HLT time!
         debugger_step(); //Step debugger if needed!
         if (CPU[activeCPU].executed) //Are we executed?
         {
            CB_handleCallbacks(); //Handle callbacks after CPU/debugger usage!
         }
      }

      //Update current timing with calculated cycles we've executed!
      if (likely(useIPSclock==0)) //Use cycle-accurate clock?
      {
         instructiontime = CPU[activeCPU].cycles*CPU_speed_cycle; //Increase timing with the instruction time!
      }
      else
      {
         instructiontime = CPU[activeCPU].executed*CPU_speed_cycle; //Increase timing with the instruction time!
      }
      last_timing += instructiontime; //Increase CPU time executed!
      timeexecuted += instructiontime; //Increase CPU executed time executed this block!

      //Tick 14MHz master clock, for basic hardware using it!
      MHZ14_ticktiming += instructiontime; //Add time to the 14MHz master clock!
      if (likely(MHZ14_ticktiming<MHZ14tick)) //To not tick some 14MHz clocks? This ix the case with most faster CPUs!
      {
         MHZ14passed = 0; //No time has passed on the 14MHz Master clock!
      }
      else
      {
         MHZ14passed = (uint_32)(MHZ14_ticktiming/MHZ14tick); //Tick as many as possible!
         MHZ14_ticktiming -= MHZ14tick*(float)MHZ14passed; //Rest the time passed!
      }

      MMU_logging |= 2; //Are we logging hardware memory accesses(DMA etc)?
      if (likely((CPU[activeCPU].halt&0x10)==0)) tickPIT(instructiontime,MHZ14passed); //Tick the PIT as much as we need to keep us in sync when running!
      updateDMA(MHZ14passed); //Update the DMA timer!
      updateMouse(instructiontime); //Tick the mouse timer if needed!
      stepDROPlayer(instructiontime); //DRO player playback, if any!
      updateMIDIPlayer(instructiontime); //MIDI player playback, if any!
      updatePS2Keyboard(instructiontime); //Tick the PS/2 keyboard timer, if needed!
      updatePS2Mouse(instructiontime); //Tick the PS/2 mouse timer, if needed!
      update8042(instructiontime); //Tick the PS/2 mouse timer, if needed!
      updateCMOS(instructiontime); //Tick the CMOS, if needed!
      updateFloppy(instructiontime); //Update the floppy!
      updateMPUTimer(instructiontime); //Update the MPU timing!
      if (useAdlib) updateAdlib(MHZ14passed); //Tick the adlib timer if needed!
      if (useGameBlaster && ((CPU[activeCPU].halt&0x10)==0)) updateGameBlaster(instructiontime,MHZ14passed); //Tick the Game Blaster timer if needed and running!
      if (useSoundBlaster && ((CPU[activeCPU].halt&0x10)==0)) updateSoundBlaster(instructiontime,MHZ14passed); //Tick the Sound Blaster timer if needed and running!
      updateATA(instructiontime); //Update the ATA timer!
      tickParallel(instructiontime); //Update the Parallel timer!
      updateUART(instructiontime); //Update the UART timer!
      if (useLPTDAC && ((CPU[activeCPU].halt&0x10)==0)) tickssourcecovox(instructiontime); //Update the Sound Source / Covox Speech Thing if needed!
      if (likely((CPU[activeCPU].halt&0x10)==0)) updateVGA(instructiontime); //Update the VGA timer when running!
      updateModem(instructiontime); //Update the modem!
      updateJoystick(instructiontime); //Update the Joystick!
      updateAudio(instructiontime); //Update the general audio processing!
      BIOSROM_updateTimers(instructiontime); //Update any ROM(Flash ROM) timers!
      MMU_logging &= ~2; //Are we logging hardware memory accesses again?
      if (--timeout==0) //Timed out?
      {
         timeout = TIMEOUT_INTERVAL; //Reset the timeout to check the next time!
         currenttiming += getnspassed(&CPU_timing); //Check for passed time!
         if (currenttiming >= timeoutCPUtime) break; //Timeout? We're not fast enough to run at full speed!
      }
   } //CPU cycle loop!

   skipCPUtiming: //Audio emulation only?
   //Slowdown to requested speed if needed!
   currenttiming += getnspassed(&CPU_timing); //Add real time!
   for (;currenttiming < last_timing;) //Not enough time spent on instructions?
   {
      currenttiming += getnspassed(&CPU_timing); //Add to the time to wait!
      delay(0); //Update to current time every instruction according to cycles passed!
   }

   float temp;
   temp = (float)MAX(last_timing,currenttiming); //Save for substraction(time executed in real time)!
   last_timing -= temp; //Keep the CPU timing within limits!
   currenttiming -= temp; //Keep the current timing within limits!

   timeemulated += timeexecuted; //Add timing for the CPU percentage to update!

   updateKeyboard(timeexecuted); //Tick the keyboard timer if needed!


That's UniPCemu's main execution loop. The CPU_exec updates EU and BIU for 1 cycle. Can't the same kind of loop method be used with your emulators?
Last edited by superfury on 2017-10-26 @ 08:46, edited 1 time in total.
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby superfury » 2017-10-26 @ 08:44

I'm just thinking, shouldn't we add some kind of register dump/memory accesses to the logs? That way we can see exactly what goes wrong when executing instruction, instead of just execution path? UniPCemu can already log those, but it's currently disabled for the common log format(since we haven't gotten to those yet).
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-26 @ 14:11

Yes, absolutely. This is what I have and I am happy to change to have something we are all happy with.

Code: Select all
EAX: 0x00008000 EBX: 0x000006f8 ECX: 0x00000000 EDX: 0x00000190
ESP: 0x00007ff8 EBP: 0x00001000 ESI: 0x00000000 EDI: 0x00000000
SS: 0x0000 DS: 0x0000 ES: 0x8000 CS: 0x0000
EIP: 0x000094a6
CF: 0 PF: 1 AF: 0 ZF: 0 SF: 0 TF: 0 IF: 0 DF: 0 OF: 0


NOTE 1: this should be a toggle though, you do not always want register dump on
NOTE 2: I admit the flags are not displayed as well as they should. For once, I am missing some and two: they should be displayed the other way around (CF is least significant bit).
NOTE 3: this should work for 16bit processors too (8088, 80286, etc) just that top 16bit of the 32bit registers (e.g. EAX) will be 0
NOTE 4: this is also missing CR registers.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-26 @ 16:30

This is what I currently use with UniPCemu(it logs all registers as well as some extra state info such as HLT and reset(first instruction after the CPU has been reset) status):

Code: Select all
OPTINLINE char decodeHLTreset(byte halted,byte isreset)
{
   if (halted)
   {
      return 'H'; //We're halted!
   }
   else if (isreset)
   {
      if (isreset&2) //Permanently reset?
      {
         return '*'; //We're permanently reset!
      }
      //Normal reset?
      return 'R'; //We're reset!
   }
   return ' '; //Nothing to report, give empty!
}

void debugger_logregisters(char *filename, CPU_registers *registers, byte halted, byte isreset)
{
   if ((DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_COMMONLOGFORMAT) || (DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_DURINGSKIPSTEP_COMMONLOGFORMAT) || (DEBUGGER_LOG==DEBUGGERLOG_DEBUGGING_COMMONLOGFORMAT)) //Common log format?
   {
      return; //No register logging, we're disabled for now!
   }
   if ((DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_NOREGISTERS) || (DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_SINGLELINE) || (DEBUGGER_LOG==DEBUGGERLOG_DEBUGGING_SINGLELINE) || (DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) || (DEBUGGER_LOG==DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) return; //Don't log the register state?
   if (!registers || !filename) //Invalid?
   {
      log_timestampbackup = log_logtimestamp(2); //Save state!
      log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
      dolog(filename,"Log registers called with invalid argument!");
      log_logtimestamp(log_timestampbackup); //Restore state!
      return; //Abort!
   }
   log_timestampbackup = log_logtimestamp(2); //Save state!
   log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
   if (EMULATED_CPU<=CPU_80286) //Emulating 80(1)86 registers?
   {
      #ifndef LOGFLAGSONLY
      dolog(filename,"Registers:"); //Start of the registers!
      dolog(filename,"AX: %04X, BX: %04X, CX: %04X, DX: %04X",registers->AX,registers->BX,registers->CX,registers->DX); //Basic registers!
      if (registers->CR0&1) //Protected mode?
      {
         dolog(filename,"CS: %04X, DS: %04X, ES: %04X, SS: %04X, TR: %04X, LDTR:%04X",registers->CS,registers->DS,registers->ES,registers->SS,registers->TR,registers->LDTR); //Segment registers!
      }
      else //Real mode?
      {
         dolog(filename,"CS: %04X, DS: %04X, ES: %04X, SS: %04X",registers->CS,registers->DS,registers->ES,registers->SS); //Segment registers!
      }
      dolog(filename,"SP: %04X, BP: %04X, SI: %04X, DI: %04X",registers->SP,registers->BP,registers->SI,registers->DI); //Segment registers!
      dolog(filename,"IP: %04X, FLAGS: %04X",registers->IP,registers->FLAGS); //Rest!
      if (EMULATED_CPU==CPU_80286) //80286 has CR0 as well?
      {
         dolog(filename, "CR0: %04X", (registers->CR0&0xFFFF)); //Rest!
         dolog(filename,"GDTR: " LONGLONGSPRINTX ", IDTR: " LONGLONGSPRINTX,(LONG64SPRINTF)registers->GDTR.data,(LONG64SPRINTF)registers->IDTR.data); //GDTR/IDTR!
      }
      #endif
      dolog(filename,"FLAGSINFO:%s%c",debugger_generateFlags(registers),decodeHLTreset(halted,isreset)); //Log the flags!
      //More aren't implemented in the 80(1/2)86!
   }
   else //80386+? 32-bit registers!
   {
      dolog(filename,"Registers:"); //Start of the registers!
      #ifndef LOGFLAGSONLY
      dolog(filename,"EAX: %08x, EBX: %08x, ECX: %08x, EDX: %08x",registers->EAX,registers->EBX,registers->ECX,registers->EDX); //Basic registers!
      
      if (registers->CR0&1) //Protected mode?
      {
         dolog(filename,"CS: %04X, DS: %04X, ES: %04X, FS: %04X, GS: %04X SS: %04X, TR: %04X, LDTR:%04X",registers->CS,registers->DS,registers->ES,registers->FS,registers->GS,registers->SS,registers->TR,registers->LDTR); //Segment registers!
      }
      else //Real mode?
      {
         dolog(filename,"CS: %04X, DS: %04X, ES: %04X, FS: %04X, GS: %04X SS: %04X",registers->CS,registers->DS,registers->ES,registers->FS,registers->GS,registers->SS); //Segment registers!
      }

      dolog(filename,"ESP: %08x, EBP: %08x, ESI: %08x, EDI: %08x",registers->ESP,registers->EBP,registers->ESI,registers->EDI); //Segment registers!
      dolog(filename,"EIP: %08x, EFLAGS: %08x",registers->EIP,registers->EFLAGS); //Rest!
      
      dolog(filename, "CR0: %08X; CR1: %08X; CR2: %08X; CR3: %08X", registers->CR0, registers->CR1, registers->CR2, registers->CR3); //Rest!
      dolog(filename, "CR4: %08X; CR5: %08X; CR6: %08X; CR7: %08X", registers->CR4, registers->CR5, registers->CR6, registers->CR7); //Rest!

      dolog(filename, "DR0: %08X; DR1: %08X; DR2: %08X; CR3: %08X", registers->DR0, registers->DR1, registers->DR2, registers->DR3); //Rest!
      if (EMULATED_CPU>=CPU_PENTIUM) //Pentium has DR4?
      {
         dolog(filename, "DR4: %08X; DR6: %08X; DR5&7: %08X", registers->DR4, registers->DR6, registers->DR7); //Rest!
      }
      else //DR4=>DR6
      {
         dolog(filename, "DR6: %08X; DR5&7: %08X", registers->DR6, registers->DR7); //Rest!
      }

      dolog(filename,"GDTR: " LONGLONGSPRINTX ", IDTR: " LONGLONGSPRINTX,(LONG64SPRINTF)registers->GDTR.data,(LONG64SPRINTF)registers->IDTR.data); //GDTR/IDTR!
      #endif
      //Finally, flags seperated!
      dolog(filename,"FLAGSINFO:%s%c",debugger_generateFlags(registers),(char)(halted?'H':' ')); //Log the flags!
   }
   log_logtimestamp(log_timestampbackup); //Restore state!
}


So in the common case, 80386+ behaviour would be forced instead of CPU-dependent. I would have to move ESP/EBP/ESI/EDI up a bit. Also, protected-mode-only registers aren't logged in real mode(unaccessable by software, might contain junk on real CPU). Seperate flags are formatted as Upper case(Set supported flag)/lower case(Cleared supported flag)/0(unknown cleared)/1(unknown set) letters and numbers, depending on CPU support(supported vs unsupported bits).
Code: Select all
char flags[256]; //Flags as a text!
static char *debugger_generateFlags(CPU_registers *registers)
{
   strcpy(flags,""); //Clear the flags!
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_CF(registers)?'C':'c'));
   sprintf(flags,"%s%u",flags,FLAGREGR_UNMAPPED2(registers));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_PF(registers)?'P':'p'));
   sprintf(flags,"%s%u",flags,FLAGREGR_UNMAPPED8(registers));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_AF(registers)?'A':'a'));
   sprintf(flags,"%s%u",flags,FLAGREGR_UNMAPPED32(registers));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_ZF(registers)?'Z':'z'));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_SF(registers)?'S':'s'));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_TF(registers)?'T':'t'));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_IF(registers)?'I':'i'));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_DF(registers)?'D':'d'));
   sprintf(flags,"%s%c",flags,(char)(FLAGREGR_OF(registers)?'O':'o'));
   if (EMULATED_CPU>=CPU_80286) //286+?
   {
      sprintf(flags,"%s%u",flags,(word)(FLAGREGR_IOPL(registers)&1));
      sprintf(flags,"%s%u",flags,(word)((FLAGREGR_IOPL(registers)&2)>>1));
      sprintf(flags,"%s%c",flags,(char)(FLAGREGR_NT(registers)?'N':'n'));
   }
   else //186-? Display as numbers!
   {
      sprintf(flags,"%s%u",flags,(word)(FLAGREGR_IOPL(registers)&1));
      sprintf(flags,"%s%u",flags,(word)((FLAGREGR_IOPL(registers)&2)>>1));
      sprintf(flags,"%s%u",flags,FLAGREGR_NT(registers));
   }
   //Higest 16-bit value!
   sprintf(flags,"%s%u",flags,FLAGREGR_UNMAPPED32768(registers));
   
   //Now the high word (80386+)!
   if (EMULATED_CPU>=CPU_80386) //386+?
   {
      sprintf(flags,"%s%c",flags,(char)(FLAGREGR_RF(registers)?'R':'r'));
      sprintf(flags,"%s%c",flags,(char)(FLAGREGR_V8(registers)?'V':'v'));
      if (EMULATED_CPU>=CPU_80486) //486+?
      {
         sprintf(flags,"%s%c",flags,(char)(FLAGREGR_AC(registers)?'A':'a'));
      }
      else //386?
      {
         sprintf(flags,"%s%u",flags,FLAGREGR_AC(registers)); //Literal bit!
      }
      if (EMULATED_CPU>=CPU_PENTIUM) //Pentium+?
      {
         sprintf(flags,"%s%c",flags,(char)(FLAGREGR_VIF(registers)?'F':'f'));
         sprintf(flags,"%s%c",flags,(char)(FLAGREGR_VIP(registers)?'P':'p'));
         sprintf(flags,"%s%c",flags,(char)(FLAGREGR_ID(registers)?'I':'i'));
      }
      else //386/486?
      {
         sprintf(flags,"%s%u",flags,FLAGREGR_VIF(registers));
         sprintf(flags,"%s%u",flags,FLAGREGR_VIP(registers));
         sprintf(flags,"%s%u",flags,FLAGREGR_ID(registers));
      }
      //Unmapped high bits!
      int i; //For counting the current bit!
      word j; //For holding the current bit!
      j = 1; //Start with value 1!
      for (i=0;i<10;i++) //10-bits value rest!
      {
         if (FLAGREGR_UNMAPPEDHI(registers)&j) //Bit set?
         {
            sprintf(flags,"%s1",flags); //1!
         }
         else //Bit cleared?
         {
            sprintf(flags,"%s0",flags); //0!
         }
         j <<= 1; //Shift to the next bit!
      }
   }
   return &flags[0]; //Give the flags for quick reference!
}


Another thing that would be needed is memory accesses themselves. UniPCemu just logs bytes accessed in three level format(direction of nesting used for the result): logical -> linear -> physical -> RAM. Logical, linear and RAM layer being dependant on the start/endpoint(no RAM for hardware, no linear/logical for Paging TLB retrieval(CR3 tables) from RAM, No logical for GDT/IDT/LDT fetches.

The start of the memory accesses is the first of those that's used during writes, but the last of those during reads(you can't log what you've read from logical/linear/physical before the RAM/hardware responds with something that's been read from it(and logs it's layer of access). The BIU always starts at the physical layer in UniPCemu(it directly accesses the hardware/RAM layer(hardware has priority over RAM). According to the profiler, that layer is the most CPU-heavy of the entire CPU emulation, probably because it requests for all hardware to respond before falling back to RAM(Using a registered hardware loop for every accessed byte).
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-26 @ 17:56

So if I understand correctly

For 286 and below you show 16 bit registers
For 386 and above you show 32 bit registers
For 386 you also show CR and DR registers.

NOTE: 386 only has CR0-CR3 ( I assume you display CR4+ because you emulate something higher?)

NOTE 2: can we show GDTR, IDTR and LDTR regardless if we are in PM or not? They exist for 286+, whether they are used or not is a different consideration.

NOTE 3: same goes for FS/GS in 386+. Show they always. They can be used outside PM, you only display them in PM.

Basically if a register is present in that architecture show it.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-26 @ 18:47

Got a good point there about showing all registers, they have values after all(initialized to zeroes by default/reset). Although real mode can't use some of them(LDTR, TR). Forgot about FS/GS: You're right about those.
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby superfury » 2017-10-26 @ 20:19

I've imptoved the logging, not requiring protected mode and only depending on the CPU when logging:
Code: Select all
F000:0000FFF0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000, EBX: 00000000, ECX: 00000000, EDX: 00000308
ESP: 00000000, EBP: 00000000, ESI: 00000000, EDI: 00000000
CS: F000, DS: 0000, ES: 0000, FS: 0000, GS: 0000 SS: 0000, TR: 0000, LDTR:0000
EIP: 0000fff0, EFLAGS: 00000002
CR0: 00000000; CR1: 00000000; CR2: 00000000; CR3: 00000000
DR0: 00000000; DR1: 00000000; DR2: 00000000; CR3: 00000000
DR6: 00000000; DR5&7: 00000000
GDTR: 000000000000FFFF, IDTR: 00000000000003FF
FLAGSINFO:c1p0a0zstido00n0rv00000000000000


Logging registers is now optional, instead of defined by debugging mode(although the no register logging mode itself blocks for compatibility with older builds, adding with the new setting).

Edit: Added space after "FLAGSINFO:" and "LDTR:".
Last edited by superfury on 2017-10-26 @ 20:26, edited 1 time in total.
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-26 @ 20:25

That looks good but few notes however:

1) can we get rid of , and ; characters ? You used them inconsistently but they do not need to be printed. A space like you have is enough
2) Why is LDTR on a separate line from GDTR and IDTR? We should have all 3 in the same line In fact I think TR should be on the same line too
3) Flags is the wrong way around. least significant bit should be to the right, not left.
4) You print a CR3 where it should be a DR3
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-26 @ 20:31

1,3&4: You're right, I'll fix those right away.
2: The difference is in the register type: TR and LDTR are essentially segment registers, just like the CS/DS/ES/FS/GS? IDTR/GDTR on the other hand are just simple pointers with limits, nothing more, unlike the others.
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-26 @ 20:33

superfury wrote:2: The difference is in the register type: TR and LDTR are essentially segment registers, just like the CS/DS/ES/FS/GS? IDTR/GDTR on the other hand are just simple pointers with limits, nothing more, unlike the others.


Yes, that makes sense actually.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-26 @ 20:46

Just implemented all of those 4 points. All that's left is reversing the flags.

Edit: One strange thing though: representing the IOPL value in the flags. Reversing those would make you read them backwards instead(as a binary value)?

Edit: Reversing complete:
Code: Select all
F000:0000FFF0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: F000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000fff0 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000FFFF IDTR: 00000000000003FF
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c


Edit: Fixed some inconsistencies with the logging, like uncapitalized register values:
Code: Select all
F000:0000FFF0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: F000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000FFF0 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000FFFF IDTR: 00000000000003FF
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c


Do notice that the carry flag in FLAGSINFO is followed by either a space(nothing special to note), R(eset of the CPU's first instruction) or *(CPU put in a permanently hanging state deliberately due to any possible cause).
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby superfury » 2017-10-26 @ 21:34

If that's correct for register state(it contains all register states now after all, depending on the CPU), we still have the issue of the memory accesses. Currently, all memory accesses are dumped during the cycle they occur(one liner or multiple lines, depending on the debugging mode). It either dumps a row to the debugger log file directly(single line for memory entry) or combines them into a single line format, seperated by ;-signs:
Code: Select all
OPTINLINE char stringsafeDebugger(byte x)
{
   return (x && (x!=0xD) && (x!=0xA))?x:(char)0x20;
}

char debugger_memoryaccess_text[1024]; //Memory access text!
char debugger_memoryaccess_line[256];

void debugger_logmemoryaccess(byte iswrite, uint_32 address, byte value, byte type)
{
   if ((DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_COMMONLOGFORMAT) || (DEBUGGER_LOG==DEBUGGERLOG_ALWAYS_DURINGSKIPSTEP_COMMONLOGFORMAT) || (DEBUGGER_LOG==DEBUGGERLOG_DEBUGGING_COMMONLOGFORMAT)) //Common log format?
   {
      return; //No memory access logging, we're disabled for now!
   }
   if (iswrite)
   {
      switch (type)
      {
         case LOGMEMORYACCESS_NORMAL:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Writing to normal memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Normal(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Normal(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_PAGED:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Writing to paged memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Paged(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Paged(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_DIRECT:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Writing to physical memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Physical(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Physical(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         default:
         case LOGMEMORYACCESS_RAM:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Writing to RAM: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"RAM(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"RAM(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_RAM_LOGMMUALL:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","MMU: Writing to real %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"RealRAM(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"RealRAM(w):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
      }
   }
   else
   {
      switch (type)
      {
         case LOGMEMORYACCESS_NORMAL:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Reading from normal memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Normal(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Normal(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_PAGED:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Reading from paged memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Paged(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Paged(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_DIRECT:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Reading from physical memory: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"Physical(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"Physical(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         default:
         case LOGMEMORYACCESS_RAM:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","Reading from RAM: %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"RAM(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"RAM(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
         case LOGMEMORYACCESS_RAM_LOGMMUALL:
            if ((DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE) && (DEBUGGER_LOG!=DEBUGGERLOG_ALWAYS_SINGLELINE_SIMPLIFIED) && (DEBUGGER_LOG!=DEBUGGERLOG_DEBUGGING_SINGLELINE_SIMPLIFIED)) //Not using a single line?
            {
               log_timestampbackup = log_logtimestamp(2); //Save state!
               log_logtimestamp(debugger_loggingtimestamp); //Are we to log the timestamp?
               dolog("debugger","MMU: Reading from real %08X=%02X (%c)",address,value,stringsafeDebugger(value));
               log_logtimestamp(log_timestampbackup); //Restore state!
            }
            else
            {
               if (strcmp(debugger_memoryaccess_text,"")==0) //Nothing logged yet?
               {
                  sprintf(debugger_memoryaccess_text,"RealRAM(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
               }
               else
               {
                  sprintf(debugger_memoryaccess_line,"RealRAM(r):%08X=%02X(%c)",address,value,stringsafeDebugger(value)); //Compact version!
                  strcat(debugger_memoryaccess_text,"; ");
                  strcat(debugger_memoryaccess_text,debugger_memoryaccess_line); //Add the line!
               }
            }
            break;
      }
   }
}


Btw the Reset flag(R at the end of the flags) is only shown when the CPU has been reset at the end of the previous running instruction. Starting to go fetching an instruction(first CPU state, which happens when the first instruction is starting to fetch, after the CPU completes an instruction(BIU becomes ready again etc. causing a reset caused by software, never happens when emulation is started(as no reset is triggered by the CPU, it's cleared when the first instruction starts fetching after all)). So it only happens when it's reset after the debugger parses an instruction and the next instruction starts fetching after the CPU is reset.
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby superfury » 2017-10-27 @ 00:16

Also, now that I see it, does the register contents need to be upper case or lower case hex?(%08X/%04X vs %08x/%04x)
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-27 @ 12:30

Probably lowercase, as that is what we've done with the other addresses.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-27 @ 13:02

OK. Now the entire universal log format is in lower case(except register names, which are in upper case). The only thing still left in upper case is the instruction opcode bytes themselves(e.g. 5b for an POP BX instruction, which follows the instruction address itself).

Now, what do we do about memory accesses(e.g. data read/written to/from memory by instructions e.g. MOV word DS:[SI], BX)? How do we log those in the common log format? Also, how do we handle stuff like the different levels of address spaces translation layers(logical -> linear -> physical -> hardware/RAM) in the common log format? The format I'm using is relatively pretty simple: just the kind of access(read or write) combined with the address translation for each layer(which may start from any point, depending on the access that's being made) and values that are transferred between the layers(the byte read/written to the storage backend(RAM or hardware like VGA)). The BIU always starts at the physical layer(it gets fed a physical address to process after all), except for the PIQ fetches themselves(which start at the logical level(CS:(E)IP)).

Any ideas?

Example log that's currently generating for the common log format with registers for the 80386 CPU running the test386.asm BIOS:
Code: Select all
f000:0000fff0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000fff0 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000045 FA cli
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000045 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000046 B0 00 mov al,00
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000046 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000048 BA 84 00 mov dx,0084
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000048 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004b EE out dx,al
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004b EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004c B4 01 mov ah,01
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004c EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004e 9E sahf
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004e EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004f 73 24 jae 00000075
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004f EFLAGS: 00000003
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1C
f000:00000051 72 23 jb 00000076
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000051 EFLAGS: 00000003
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1C
f000:00000076 72 DC jb 00000054
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000076 EFLAGS: 00000003
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1C
f000:00000054 B4 40 mov ah,40
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000054 EFLAGS: 00000003
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1C


Edit: Btw(a bit offtopic), I just noticed a new SDL2 2.0.7 having been released. I sure hope that fixes the problem with SDL2.dll crashing within it's own thread when disconnecting from Windows 10 Remote Desktop(it started crashing with 2.0.6 for unknown reasons, nothing to do with my emulator).
Edit: Unfortunately, it still crashes:
Code: Select all
Exception thrown at 0x000000006C82634B (SDL2.dll) in UniPCemu_x64.exe:
0xC0000005: Access violation reading location 0x0000000000000000)
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-27 @ 15:16

Show us an example of what you have given an instruction that writes out something, or reads something.
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

Re: Common log format

Postby superfury » 2017-10-27 @ 16:00

OK. I've made a little log of the first BIOS ROM executions with the full memory log enabled(seperate line for each layer, used with the normal debugging log modes in UniPCemu):
Code: Select all
Reading from physical memory: FFFFFFF0=EA (ê)
Reading from paged memory: FFFFFFF0=EA (ê)
Reading from physical memory: FFFFFFF1=45 (E)
Reading from paged memory: FFFFFFF1=45 (E)
Reading from physical memory: FFFFFFF2=00 ( )
Reading from paged memory: FFFFFFF2=00 ( )
Reading from physical memory: FFFFFFF3=00 ( )
Reading from paged memory: FFFFFFF3=00 ( )
Reading from physical memory: FFFFFFF4=F0 (ð)
Reading from paged memory: FFFFFFF4=F0 (ð)
Reading from physical memory: FFFFFFF5=32 (2)
Reading from paged memory: FFFFFFF5=32 (2)
Reading from physical memory: FFFFFFF6=31 (1)
Reading from paged memory: FFFFFFF6=31 (1)
Reading from physical memory: FFFFFFF7=2F (/)
Reading from paged memory: FFFFFFF7=2F (/)
f000:0000fff0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000fff0 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
Reading from physical memory: 000F0045=FA (ú)
Reading from paged memory: 000F0045=FA (ú)
Reading from physical memory: 000F0046=B0 (°)
Reading from paged memory: 000F0046=B0 (°)
Reading from physical memory: 000F0047=00 ( )
Reading from paged memory: 000F0047=00 ( )
Reading from physical memory: 000F0048=BA (º)
Reading from paged memory: 000F0048=BA (º)
Reading from physical memory: 000F0049=84 („)
Reading from paged memory: 000F0049=84 („)
Reading from physical memory: 000F004A=00 ( )
Reading from paged memory: 000F004A=00 ( )
Reading from physical memory: 000F004B=EE (î)
Reading from paged memory: 000F004B=EE (î)
Reading from physical memory: 000F004C=B4 (´)
Reading from paged memory: 000F004C=B4 (´)
Reading from physical memory: 000F004D=01 ()
Reading from paged memory: 000F004D=01 ()
Reading from physical memory: 000F004E=9E (ž)
Reading from paged memory: 000F004E=9E (ž)
Reading from physical memory: 000F004F=73 (s)
Reading from paged memory: 000F004F=73 (s)
Reading from physical memory: 000F0050=24 ($)
Reading from paged memory: 000F0050=24 ($)
Reading from physical memory: 000F0051=72 (r)
Reading from paged memory: 000F0051=72 (r)
Reading from physical memory: 000F0052=23 (#)
Reading from paged memory: 000F0052=23 (#)
Reading from physical memory: 000F0053=F4 (ô)
Reading from paged memory: 000F0053=F4 (ô)
Reading from physical memory: 000F0054=B4 (´)
Reading from paged memory: 000F0054=B4 (´)
f000:00000045 FA cli
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000045 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000046 B0 00 mov al,00
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000046 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
Reading from physical memory: 000F0055=40 (@)
Reading from paged memory: 000F0055=40 (@)
Reading from physical memory: 000F0056=9E (ž)
Reading from paged memory: 000F0056=9E (ž)
Reading from physical memory: 000F0057=75 (u)
Reading from paged memory: 000F0057=75 (u)
Reading from physical memory: 000F0058=1C ()
Reading from paged memory: 000F0058=1C ()
f000:00000048 BA 84 00 mov dx,0084
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000048 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004b EE out dx,al
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004b EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
Reading from physical memory: 000F0059=74 (t)
Reading from paged memory: 000F0059=74 (t)
Reading from physical memory: 000F005A=1D ()
Reading from paged memory: 000F005A=1D ()
Reading from physical memory: 000F005B=F4 (ô)
Reading from paged memory: 000F005B=F4 (ô)
Reading from physical memory: 000F005C=B4 (´)
Reading from paged memory: 000F005C=B4 (´)
f000:0000004c B4 01 mov ah,01
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004c EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004e 9E sahf
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004e EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c


Also, one with the single line format logging method instead(used with the cycle logging mode of UniPCemu, a tab at the start being the remnant of the seperation process for easy parsability(usually the first column is the executed cycle, which doesn't appear here), while easy to parse due to identifying tabs at the start(think Makefile rules of an instruction executing, although it's just remnants of UniPCemu's state logging method). It's essentially lines of one byte/word/dword being read and the path each byte takes):
Code: Select all
      Physical(r):FFFFFFF0=EA(ê); Paged(r):FFFFFFF0=EA(ê); Physical(r):FFFFFFF1=45(E); Paged(r):FFFFFFF1=45(E); Physical(r):FFFFFFF2=00( ); Paged(r):FFFFFFF2=00( ); Physical(r):FFFFFFF3=00( ); Paged(r):FFFFFFF3=00( )
      Physical(r):FFFFFFF4=F0(ð); Paged(r):FFFFFFF4=F0(ð); Physical(r):FFFFFFF5=32(2); Paged(r):FFFFFFF5=32(2); Physical(r):FFFFFFF6=31(1); Paged(r):FFFFFFF6=31(1); Physical(r):FFFFFFF7=2F(/); Paged(r):FFFFFFF7=2F(/)
f000:0000fff0 EA 45 00 00 F0 jmp f000:00000045
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000fff0 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
      Physical(r):000F0045=FA(ú); Paged(r):000F0045=FA(ú); Physical(r):000F0046=B0(°); Paged(r):000F0046=B0(°); Physical(r):000F0047=00( ); Paged(r):000F0047=00( ); Physical(r):000F0048=BA(º); Paged(r):000F0048=BA(º)
      Physical(r):000F0049=84(„); Paged(r):000F0049=84(„); Physical(r):000F004A=00( ); Paged(r):000F004A=00( ); Physical(r):000F004B=EE(î); Paged(r):000F004B=EE(î); Physical(r):000F004C=B4(´); Paged(r):000F004C=B4(´)
      Physical(r):000F004D=01(); Paged(r):000F004D=01(); Physical(r):000F004E=9E(ž); Paged(r):000F004E=9E(ž); Physical(r):000F004F=73(s); Paged(r):000F004F=73(s); Physical(r):000F0050=24($); Paged(r):000F0050=24($)
      Physical(r):000F0051=72(r); Paged(r):000F0051=72(r); Physical(r):000F0052=23(#); Paged(r):000F0052=23(#); Physical(r):000F0053=F4(ô); Paged(r):000F0053=F4(ô); Physical(r):000F0054=B4(´); Paged(r):000F0054=B4(´)
f000:00000045 FA cli
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000045 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000046 B0 00 mov al,00
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000046 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:00000048 BA 84 00 mov dx,0084   Physical(r):000F0055=40(@); Paged(r):000F0055=40(@); Physical(r):000F0056=9E(ž); Paged(r):000F0056=9E(ž); Physical(r):000F0057=75(u); Paged(r):000F0057=75(u); Physical(r):000F0058=1C(); Paged(r):000F0058=1C()
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000308
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 00000048 EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004b EE out dx,al
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004b EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004c B4 01 mov ah,01   Physical(r):000F0059=74(t); Paged(r):000F0059=74(t); Physical(r):000F005A=1D(); Paged(r):000F005A=1D(); Physical(r):000F005B=F4(ô); Paged(r):000F005B=F4(ô); Physical(r):000F005C=B4(´); Paged(r):000F005C=B4(´)
Registers:
EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004c EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c
f000:0000004e 9E sahf
Registers:
EAX: 00000100 EBX: 00000000 ECX: 00000000 EDX: 00000084
ESP: 00000000 EBP: 00000000 ESI: 00000000 EDI: 00000000
CS: f000 DS: 0000 ES: 0000 FS: 0000 GS: 0000 SS: 0000 TR: 0000 LDTR: 0000
EIP: 0000004e EFLAGS: 00000002
CR0: 00000000 CR1: 00000000 CR2: 00000000 CR3: 00000000
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: 00000000 DR5&7: 00000000
GDTR: 000000000000ffff IDTR: 00000000000003ff
FLAGSINFO: 00000000000000vr0n00oditsz0a0p1c


Ideas on those formats(NULL byte as well as carriage return and backspace being patched to space character instead with text representation between parenteses)?
superfury
l33t
 
Posts: 2416
Joined: 2014-3-08 @ 11:25
Location: Netherlands

Re: Common log format

Postby vladstamate » 2017-10-27 @ 16:21

When would those be different? In PM when paging is on?

Code: Select all
Reading from physical memory: 000F0059=74 (t)
Reading from paged memory: 000F0059=74 (t)


By paged memory you mean virtual memory/address?
User avatar
vladstamate
Oldbie
 
Posts: 828
Joined: 2015-8-23 @ 01:43

PreviousNext

Return to PC Emulation

Who is online

Users browsing this forum: No registered users and 1 guest