BrainStreamLogFile

From TSG Doc
Revision as of 14:10, 21 September 2018 by Wiki-admin (talk | contribs) (Created page with "<!---Start1---> =Log file = __TOC__ BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your e...")
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to navigation Jump to search

Log file

BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your experiment. You can find the log file in the [.DocsSectionsPathsFolders#OutputFolder runfolder] of your experiment.

As the log file contains a lot of information it is sometimes difficult to find the information you are looking for. In the following, we will show which information is included in the log file and where it can be found. We will use this log file as an example. The log file belongs to the experiment described [.DocsSectionsExampleSentences here].

Date and time

Each new line of the log file begins with a date and time: 

09Nov11|10:47:38.928 INFO >

Date and time are derived from the computer which executes the actions. Note that if you are using [.DocsSectionsParallelMode#SecClients parallel clients] on multiple computers, computer times of the different machines may not be synchronous. Although this may be confusing when reading the log file, it has no influence on the timing of executed actions.

The date and time can be followed either by INFO or WARN. This is related to the blocksetting [.DocsSectionsBlockFile#KeyVerbosityLevel VerbosityLevel]. If VerbosityLevel was set to INFO, all information in INFO and WARN lines of the log file have also been shown in the Matlab command window during the experiment. If VerbosityLevel was set to WARNING, only the WARN lines of the log file have been shown in the Matlab command window. Additionally, you can use the [.DocsSectionsProgrmmersGuide#bs_msg bs_msg] and [.DocsSectionsProgrmmersGuide#bs_warn bs_warn] functions to write messages to the log file yourself.

Experiment initialization

The first part of the log file describes everything that happened before the onset of BrainStream processing, that is, before the BS_INIT marker arrives. For example, you may find information about

  • reading settings from the [.DocsSectionsBuildingExperiments#SecBlock block file]
    09Nov11|10:47:46.593 INFO >	Read from block settings: [[TriggerSource|Trigger Source]] = default

09Nov11|10:47:46.593 INFO > Default used for [[TriggerDef|Trigger Def]] (failed reading from block settings

  • loading files or functions
    09Nov11|10:47:47.836 INFO >	Load experiment definition tables/files

09Nov11|10:47:48.248 INFO > Preload user defined function

  • connecting to the FieldTrip buffer or [.DocsSectionsParallelMode#SecClients clients]
    09Nov11|10:47:39.186 INFO >	Initialize streaming from simulated data to: buffer://localhost:1975

09Nov11|10:47:44.855 INFO > Initialize reading from [[FieldTrip|Field Trip]] buffer: localhost:1975:biosemi_active2

09Mar11|16:14:08.347 INFO > Read from block settings: stim = localhost

09Mar11|16:14:08.350 INFO > server socket for lab 1, client stim, is connected to 127.0.0.1 (localhost), port 5001

Expanded Actions table

In addition, the log file always contains the [.DocsSectionsPlugIns#TableExpansion expanded] [.DocsSectionsBuildingExperiments#SecActions Actions table]. Although it looks a bit messy, it has the exact same content as the Actions table in your .edt or .xls file. 

09Nov11|10:47:48.241 INFO >	Combined complete experiment definition table:
marker	time	function	feval	looptick	client	stimsequence	character	sequence_count	epoch_count	fig
BS_INIT	EVENT	bs_send_buffer_marker('init_sequence','eeg',0,'now')				[]	[]	0	[]	[]
init_sequence	EVENT	initSequence(), bs_send_buffer_marker('next_sequence','eeg',0,'now')				put				
next_sequence	EVENT	nextSequence()				get		$self+1,get		get,put
start_sequence	button_1	displayString(''), bs_send_buffer_marker('next_epoch','eeg',0,'now')				get		get	0	get
next_epoch	EVENT	nextEpoch()				get	put	get	$self+1,get	
proc_epoch	EVENT	displayString(), bs_send_buffer_marker('next_epoch','eeg',0.25,'now')					get			get
proc_epoch	DATA	bs_disp('process the data')								
end_sequence	EVENT	bs_send_buffer_marker('next_sequence','eeg',1,'now')								
button_1	EVENT									
BS_QUIT	EVENT	bs_abort_experiment()								
BS_ABORT	EVENT	bs_abort_experiment()								
BS_EXIT	EVENT	bs_stop_experiment()

BrainStream processing

The onset of BrainStream processing is indicated by the line: 

09Nov11|10:47:49.132 INFO >	Start of Brainstream processing, initialize block

In the following section of the log file, each line of asterisks separates actions belonging to different [.DocsSectionsImportantConcepts#SecEvents events]. The name of the event is shown in brackets.

Action execution

In the example experiment of this log file, the BS_INIT marker triggered the modification of three user defined variables and the execution of a function. According to the [.DocsSectionsTableHandling fixed order] in which BrainStream executes actions, first the modification actions are completed and then the function is executed. This is the information in the log file: 

09Nov11|10:47:49.155 INFO >	'''***''' (                  BS_INIT) '''*************************************************************'''
09Nov11|10:47:49.156 INFO >	  9.80 (eeg:#1.00)     9.80    10.66	act: modvar	(t=EVENT)	BS_INIT	
09Nov11|10:47:49.160 INFO >	  9.80 (eeg:#1.00)     9.80    10.67	act: exefnc	(t=EVENT)	BS_INIT

The first number in each row specifies the time at which the marker arrives. Between parentheses, the corresponding sample numbers of the data from different data sources are given. In this case, there is only one data source, which is called 'eeg'. The sample at which the BS_INIT marker arrives is given sample number 1.

The second number specifies the time at which the actions described in this line of the log file were scheduled to take place, whereas the third number specifies the time at which the action actually was executed. In the Actions table of the example experiment, all actions for the BS_INIT marker were scheduled for execution at time point EVENT, that is, as soon as the marker arrives. Thus, the scheduled time point is equal to the time of marker arrival. The third row shows that the modification actions took place 860 ms after the scheduled time, followed by the function execution 870 ms after the scheduled time.

The fourth column shows the [.DocsSectionsTableHandling#ActionType type] of action that is executed: retrieving variable content (getvar), modifying variable content (modvar), executing functions (exefnc), or storing variable content (putvar). The fifth column shows the time point of the action as specified in the Actions table. The last column shows again the name of the marker that triggers the action.

Data selection

In the example experiment, each time the proc_epoch marker arrived, variable content was retrieved from the global variables and two functions were executed. In addition, one second of data was selected from the data source called 'eeg'. When the data had been selected, a third function was executed.

In this experiment, the first proc_epoch marker arrived at time 20.64, or EEG sample number 2776. Immediately, content of variables was retrieved (getvar) and the functions were executed (exefnc): 

09Nov11|10:47:59.161 INFO >	'''***''' (               proc_epoch) '''*************************************************************'''
09Nov11|10:47:59.161 INFO >	 20.64 (eeg:#2776.00)    20.64    20.67	act: getvar	(t=EVENT)	proc_epoch	
09Nov11|10:47:59.163 INFO >	 20.64 (eeg:#2776.00)    20.64    20.67	act: exefnc	(t=EVENT)	proc_epoch

As we wanted to select one second of data, starting at the onset of marker proc_epoch, the execution of the last function could not take place before one second had elapsed. The log file indeed shows that one second after event onset, data was selected and the function was executed: 

09Nov11|10:48:00.151 INFO >	'''***''' (               proc_epoch) '''*************************************************************'''
09Nov11|10:48:00.152 INFO >	 20.64 (eeg:#2776.00)    21.64    21.66	act: exefnc	(t=DATA, eeg:#2776-#3031)	proc_epoch

The time of event onset is the same as for the first two actions (20.64 seconds or EEG sample number 2776). The scheduled time for the execution of the function was one second after event onset (21.64 seconds), and the actual execution time was 20 ms later (21.66 seconds). In the next column, we see that a piece of data with sample numbers 2776 to 3031 has been selected from the EEG data source.

This example illustrates the point that although al actions following a line of asterisks belong to the same event, it is not necessarily the case that all actions belonging to the same event are listed under one and the same line of asterisks in the log file. In this experiment, three next_epoch and proc_epoch markers arrive before the last action of the first proc_epoch marker is executed: 

09Nov11|10:47:59.161 INFO >	'''***''' (               proc_epoch) '''*************************************************************'''
09Nov11|10:47:59.161 INFO >	 20.64 (eeg:#2776.00)    20.64    20.67	act: getvar	(t=EVENT)	proc_epoch	
09Nov11|10:47:59.163 INFO >	 20.64 (eeg:#2776.00)    20.64    20.67	act: exefnc	(t=EVENT)	proc_epoch	
09Nov11|10:47:59.435 INFO >	'''***''' (               next_epoch) '''*************************************************************'''
09Nov11|10:47:59.436 INFO >	 20.93 (eeg:#2850.00)    20.93    20.94	act: modvar	(t=EVENT)	next_epoch	
09Nov11|10:47:59.438 INFO >	 20.93 (eeg:#2850.00)    20.93    20.95	act: getvar	(t=EVENT)	next_epoch	
09Nov11|10:47:59.439 INFO >	 20.93 (eeg:#2850.00)    20.93    20.95	act: exefnc	(t=EVENT)	next_epoch	
09Nov11|10:47:59.442 INFO >	 20.93 (eeg:#2850.00)    20.93    20.95	act: putvar	(t=EVENT)	next_epoch		
	.
	.
	.
09Nov11|10:48:00.151 INFO >	'''***''' (               proc_epoch) '''*************************************************************'''
09Nov11|10:48:00.152 INFO >	 20.64 (eeg:#2776.00)    21.64    21.66	act: exefnc	(t=DATA, eeg:#2776-#3031)	proc_epoch

In the log file, you can identify actions that belong to the same event by looking at the time of event onset, i.e. the first number that is specified in a row. You can see that the actions described in the two sections of the proc_epoch marker belong to the same event, because the time point of event onset is 20.64 in both cases.

Error messages

If something goes wrong during your experiment, error messages are shown on the screen. You can find these error messages in the log file as well. Error messages usually appear at the end of the log file, because processing is interrupted by the error.

An example: 

09Mar11|16:14:11.221 INFO >	Read from block settings: [[ReferenceFolder|Reference Folder]] = /Volumes/BCI_Stims/own_experiments/visual/Hexospell
Reference to non-existent field 'layer16'.
Error in :mkSymbolsHex, line :  41
Error in :ExecFncs, line :  34
Error in :ProcessEvents/action_execfnc, line :  393
Error in :ProcessEvents, line :  113
Error in :RunBCI3, line :  99
Error in :BCI, line :  50
Error in :brainstream_block, line :  35
Error in :StartBrainStream/LaunchBCIApplication, line :  206
Error in :StartBrainStream/pushbuttonStart_Callback, line :  335


Retrieved from "http://tsgdoc.socsci.ru.nl/index.php?title=BrainStreamLogFile&oldid=4511"