Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

loading large file needs long time #1189

Open
likun2 opened this issue Dec 24, 2024 · 8 comments
Open

loading large file needs long time #1189

likun2 opened this issue Dec 24, 2024 · 8 comments

Comments

@likun2
Copy link

likun2 commented Dec 24, 2024

I have a 40MB elf file that takes about 5 minutes to load into the board using openocd and gdb. The reason why it took so long is because there is a delay function in the abstract_cmd_batch_check_and_clear_cmderr function, which is increase_ac_busy_delay.

static int abstract_cmd_batch_check_and_clear_cmderr(struct target *target,
		const struct riscv_batch *batch, size_t abstractcs_read_key,
		uint32_t *cmderr)
{
	uint32_t abstractcs = riscv_batch_get_dmi_read_data(batch,
			abstractcs_read_key);
	int res;
	LOG_DEBUG_REG(target, DM_ABSTRACTCS, abstractcs);
	if (get_field32(abstractcs, DM_ABSTRACTCS_BUSY) != 0) {
		res = wait_for_idle(target, &abstractcs);
		if (res != ERROR_OK)
			goto clear_cmderr;
		res = increase_ac_busy_delay(target);
		if (res != ERROR_OK)
			goto clear_cmderr;
	}
	*cmderr = get_field32(abstractcs, DM_ABSTRACTCS_CMDERR);
	if (*cmderr == CMDERR_NONE)
		return ERROR_OK;
	res = ERROR_FAIL;
	LOG_TARGET_DEBUG(target,
			"Abstract Command execution failed (abstractcs.cmderr = %" PRIx32 ").",
			*cmderr);
clear_cmderr:
	/* Attempt to clear the error. */
	/* TODO: can we add a more substantial recovery if the clear operation fails? */
	if (dm_write(target, DM_ABSTRACTCS, DM_ABSTRACTCS_CMDERR) != ERROR_OK)
		LOG_TARGET_ERROR(target, "could not clear abstractcs error");
	return res;
}

How can we eliminate the impact of this delay function
@en-sc

@likun2 likun2 changed the title load large file needs long time loading large file needs long time Dec 24, 2024
@en-sc
Copy link
Collaborator

en-sc commented Dec 25, 2024

@likun2, thank you for reporting the issue.
Unfortunately there is not enough information to solve it.

While abstract_cmd_batch_check_and_clear_cmderr() does increase the delay used after starting an abstract command, this is only done if the delay is insufficient (the read of abstractcs has returned abstractcs.busy). It is needed to wait for abstractcs.busy to go low to continue working with the target.

Moreover, JTAG is quite slow. 40MB in 5 minutes is about 1118481 bits per second which requires at least 1118 kHz TCK clock (and this is the lower limit since there are various overheads in the process). What is the JTAG speed you are using?

In general, to further investigate the issue, I'd like to ask you to attach -d3 log of loading an image to the target. This does not need to be a particularly large image -- 10kB should be sufficient.
Also the config file you are using will be very helpfull.
You can obtain the log by running:

> dd if=/dev/zero of=10kB.bin count=10 bs=1kB
> openocd ... -c init -c 'load_image 10kB.bin <memory_start_addr>' -c shutdown -d3 -l <log_filename>

@likun2
Copy link
Author

likun2 commented Dec 26, 2024

@en-sc ,thank you for responding.
I set the adapter speed to 1000 in the cfg file. When I change the speed value, the loading time does not decrease. When I delete the increase_ac_busy_delay functions in the abstract_cmd_batch_check_and_clear_cmdeer function, the file can still be loaded successfully, and the loading time will be reduced to about 1 minute. This delay effect is only reflected when loading large elf files, and loading small files will be faster. I checked the riscv_scan_increase_delay function and found that the delay_step gradually increases as the delay increases. Does this mean that the larger the loaded file, the longer the delay time.

@en-sc
Copy link
Collaborator

en-sc commented Dec 26, 2024

I checked the riscv_scan_increase_delay function and found that the delay_step gradually increases as the delay increases. Does this mean that the larger the loaded file, the longer the delay time.

The idea is -- the delay is increased after abstractcs.busy is observed. Once the delay is sufficient and abstractcs.busy is not observed anymore it is not increased further.

E.g. running on Spike with --dm-abstract-rti=10, the first command execution results in abstractcs.busy set since there is no delay at first:

Debug: 161 3 batch.c:249 log_batch(): 40b w 00321008 @17 -> + 00000000 @00; 0i
Debug: 162 3 batch.c:190 log_dmi_decoded(): write: command=0x321008 {control=0x321008}
Debug: 163 3 batch.c:249 log_batch(): 40b r 00000000 @16 -> + 00321008 @17; 0i
Debug: 164 3 batch.c:249 log_batch(): 40b - 00000000 @00 -> + 06001002 @16; 0i
Debug: 165 3 batch.c:190 log_dmi_decoded(): read: abstractcs=0x6001002 {datacount=2 busy=busy progbufsize=6}
Debug: 166 3 riscv-013.c:624 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x6001002 {datacount=2 relaxedpriv=full_checks busy=busy progbufsize=6 cmderr=none}

The next time an increased delay is used (1i at the end indicates that there is one extra TCK clock spent in Run-Test-Idle):

Debug: 181 4 batch.c:249 log_batch(): 40b w 00320301 @17 -> + 00000000 @00; 1i

Once the delay reaches 7 -- it becomes enough and abstractcs.busy is low on the first read:

Debug: 332 5 batch.c:249 log_batch(): 40b w 00321008 @17 -> + 00000000 @00; 7i
Debug: 333 5 batch.c:190 log_dmi_decoded(): write: command=0x321008 {control=0x321008}
Debug: 334 5 batch.c:249 log_batch(): 40b r 00000000 @16 -> + 00321008 @17; 0i
Debug: 335 5 batch.c:249 log_batch(): 40b - 00000000 @00 -> + 06000002 @16; 0i
Debug: 336 5 batch.c:190 log_dmi_decoded(): read: abstractcs=0x6000002 {datacount=2 progbufsize=6}
Debug: 337 5 riscv-013.c:624 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x6000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=6 cmderr=none}

From this point on the delay of 7 Run-Test-Idle cycles is used.

So no, loading larger files does not result in longer delays.

To reiterate: I will not be able to help you without the logs.

@likun2
Copy link
Author

likun2 commented Dec 27, 2024

The load command log is as follow
load_command.txt
There are 2 cfg files
cfg1is

adapter speed 1000
adapter driver ftdi
ftdi vid_pid 0x0403 0x6011
ftdi channel 1
ftdi layout_init 0x00e8 0x60eb
ftdi layout_signal nTRST -ndata 0x0010
reset_config none

transport select jtag

set _CHIPNAME riscv
jtag newtap $_CHIPNAME cpu -irlen 5 -expected-id 0x10000c59

foreach t [target names] {
   puts [format "Target: %s\n" $t]
}

gdb_report_register_access_error enable

scan_chain

cfg2 is

set _CHIPNAME riscv
set _TARGETNAME $_CHIPNAME.cpu
target create $_TARGETNAME riscv -chain-position $_TARGETNAME -rtos hwthread

riscv set_command_timeout_sec 120

scan_chain

@en-sc
Copy link
Collaborator

en-sc commented Dec 27, 2024

@likun2, you've cut out the part where the delay grows.

Before the cut the delay is zero:

Debug: 15763 143332 riscv-013.c:432 riscv_log_dmi_scan(): 41b w 69e3fed7 @04 -> ?; 0i

After the cut it is already huge (445):

Debug: 2520113 536604 riscv-013.c:432 riscv_log_dmi_scan(): 41b w 30314c4c @04 -> ?; 445i

My assumption is: maybe there is some memory that takes longer to access that is written in the cut-out part of the log?

If the data you are loading is sensitive please consider loading a bunch of zeroes instead:

> dd if=/dev/zero of=10kB.bin count=10 bs=1kB
> openocd ... -c init -c 'load_image 10kB.bin <memory_start_addr>' -c shutdown -d3 -l <log_filename>

@likun2 please attach the part of the log where the delay increases.

@likun2
Copy link
Author

likun2 commented Dec 30, 2024

The log is huge so I seperate it to 3 parts.
load.log
load2.txt
load3.txt

@TommyMurphyTM1234
Copy link
Collaborator

The log is huge so I seperate it to 3 parts. load.log load2.txt load3.txt

Large logs can just be zipped and uploaded in compressed form.

@likun2
Copy link
Author

likun2 commented Jan 2, 2025

@TommyMurphyTM1234 thank you for responding.
I compressed the log file and uploaded it again.
log.zip
@en-sc

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants