Author Topic: FIO_SeekSkipFile testing  (Read 26474 times)

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
FIO_SeekSkipFile testing
« on: July 28, 2014, 01:40:28 PM »
After seeing the problems with FIO_SeekFile on large files (greater than 2 GB) and discussing the issue with g3gg0, I've removed the FIO_SeekFile stub and replaced all the calls with FIO_SeekSkipFile (which should handle large files).

To make sure all cameras will get the correct behavior, I've added some testing routines for this function in Debug -> Burn-in tests -> Stubs API tests; credits go to g3gg0 (he told me exactly what I should test for, to make sure large files are handled correctly). Please run the tests and paste the log file in this thread.

Here's how a successful test looks like:
Code: [Select]
...
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
...

Here's how a failed test may look like (I've ran the test on 5D3 123 with the FIO_SeekFile address instead of FIO_SeekSkipFile, to make sure this mistake is caught).
Code: [Select]
...
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[FAIL] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x20a
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[FAIL] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0xffffffff
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[FAIL] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0xffffffff
[FAIL] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0xffffffff
[FAIL] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0xffffffff
[FAIL] FIO_GetFileSize_direct("test.dat") => 0x82000000
...

To minimize the situations where broken core functionality enters the nightly builds, and a bug is reported after 5 months, I'll break all the nightly builds for which I don't receive a testing log within the next 5 days.

Some usage notes:
- FIO_SeekSkipFile always returns the absolute position after seeking
- old FIO_SeekFile was able to seek past the end of the file on 5D2, but FIO_SeekSkipFile is not
- on 5D3 and 60D, FIO_SeekSkipFile can seek past the end of the file, but it's very slow (5D3 was fairly fast, but 60D could not finish creating a 2GB file in 30 minutes)
=> please avoid seeking past the end of the file; even if it may work on your camera, it's not portable; use FIO_WriteFile instead.

TODO:
- make sure all the stubs we use are covered by such tests (especially new and recent ones)
- move these tests to a module, because they are pretty large for some cameras (currently 25KB)
- improve the tests (both more thorough and more readable - because these tests also serve as documentation on how these stubs are expected to behave)
- merge the memory checking module into this one, to have all the internal tests in one place
- move the existing tests from "don't click me" in the menu

ayshih

  • Contributor
  • Senior
  • *****
  • Posts: 266
Re: FIO_SeekSkipFile testing
« Reply #1 on: July 28, 2014, 02:01:46 PM »
All passes for 50D (all other tests too)
Code: [Select]
...
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
...

I'm surprised that backwards seeking from the end appears to work fine.  I thought I encountered issues with that when I modified mlv_play, so I had added additional statements to turn them into absolute seeks.  I'm going to see if I can recreate that bug.
Canon EOS 50D | 17–40mm f/4L & 70–300mm f/4.5–5.6 DO IS | Lexar 1066x

Greg

  • Contributor
  • Hero Member
  • *****
  • Posts: 607
Re: FIO_SeekSkipFile testing
« Reply #2 on: July 28, 2014, 02:15:37 PM »
500D :
Code: [Select]
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020

ayshih

  • Contributor
  • Senior
  • *****
  • Posts: 266
Re: FIO_SeekSkipFile testing
« Reply #3 on: July 28, 2014, 03:27:31 PM »
I'm surprised that backwards seeking from the end appears to work fine.  I thought I encountered issues with that when I modified mlv_play, so I had added additional statements to turn them into absolute seeks.  I'm going to see if I can recreate that bug.
Ah, I confirmed the bug with backwards searching (whether SEEK_CUR or SEEK_END).  The problem is not with FIO_SeekSkipFile itself, but rather with not exercising enough caution when passing in negative integers.  Consider the difference:
Code: [Select]
[FAIL] FIO_SeekSkipFile(f, -sizeof(f), SEEK_END) => 0xffffffff
[Pass] FIO_SeekSkipFile(f, -(uint64_t)sizeof(f), SEEK_END) => 0x8200000c
The problem is that sizeof returns a 32-bit integer, so the negation is performed at the 32-bit level rather than the 64-bit level in the first call.  The type needs to be cast explicitly to avoid this bug.  There is one call in raw_rec.c that needs to be fixed (reading the footer), and there may be others.

The stubs tests work because they are constants, and the compiler correctly determines that they should be 64-bit integers. 
Canon EOS 50D | 17–40mm f/4L & 70–300mm f/4.5–5.6 DO IS | Lexar 1066x

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #4 on: July 28, 2014, 03:31:09 PM »
If we use int64_t in fio-ml.h, does it help?

ayshih

  • Contributor
  • Senior
  • *****
  • Posts: 266
Re: FIO_SeekSkipFile testing
« Reply #5 on: July 28, 2014, 04:17:03 PM »
I tried that, but it didn't appear to make a difference.  I ran out of time to test more, so I won't be able to look into it further until my evening.
Canon EOS 50D | 17–40mm f/4L & 70–300mm f/4.5–5.6 DO IS | Lexar 1066x

Greg

  • Contributor
  • Hero Member
  • *****
  • Posts: 607
Re: FIO_SeekSkipFile testing
« Reply #6 on: July 28, 2014, 05:23:05 PM »
500D : (commit 5e2dabf)
Code: [Select]
[FAIL] err = FIO_SeekSkipFile(f, (int64_t)0x8000000000000000, SEEK_CUR) => 0x30
[FAIL] err == (int64_t)0xFFFFFFFFFFFFFFFF => 0x0

jpaana

  • New to the forum
  • *
  • Posts: 28
Re: FIO_SeekSkipFile testing
« Reply #7 on: July 29, 2014, 10:25:52 AM »
On EOS-M the full test causes stack overflow in idle task during the malloc tests, but anything up to that works:

Code: [Select]
[Pass] buf = fio_malloc(0x1000000) => 0x4de1a094
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] FIO_RemoveFile("test.dat") => 0x0

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #8 on: July 29, 2014, 10:42:09 AM »
Stack overflow errors are not funny. Can you try to locate the test that causes it?

jpaana

  • New to the forum
  • *
  • Posts: 28
Re: FIO_SeekSkipFile testing
« Reply #9 on: July 29, 2014, 02:22:07 PM »
Stack overflow errors are not funny. Can you try to locate the test that causes it?

Without either of the memory test loops I can now (after the recursive lock fix) run all tests successfully. The first memory test gives 400 failures:

[FAIL] p = (void*)_shoot_malloc(24*1024*1024) => 0x0
[FAIL] UNCACHEABLE(p) => 0x40000000

Reducing that allocation size to 20 megs or switching the camera to small JPEG makes it work. Debug menu gives maximum contiguous block as 20MB with my normal RAW settings, 29 megs with S3 JPEG.

The second memory test loop partially hangs camera, doesn't give the stack overflow now, camera can be shut down, but leaves the led on, I'll double check the stubs just in case and add some more prints.

mk11174

  • Contributor
  • Hero Member
  • *****
  • Posts: 809
Re: FIO_SeekSkipFile testing
« Reply #10 on: July 29, 2014, 02:49:54 PM »
700D
Code: [Select]
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] FIO_RemoveFile("test.dat") => 0x0
500D/T1i  550D/T2i  600D/T3i  700D/T5i

jpaana

  • New to the forum
  • *
  • Posts: 28
Re: FIO_SeekSkipFile testing
« Reply #11 on: July 29, 2014, 02:52:22 PM »
Without either of the memory test loops I can now (after the recursive lock fix) run all tests successfully. The first memory test gives 400 failures:

[FAIL] p = (void*)_shoot_malloc(24*1024*1024) => 0x0
[FAIL] UNCACHEABLE(p) => 0x40000000

Reducing that allocation size to 20 megs or switching the camera to small JPEG makes it work. Debug menu gives maximum contiguous block as 20MB with my normal RAW settings, 29 megs with S3 JPEG.

The second memory test loop partially hangs camera, doesn't give the stack overflow now, camera can be shut down, but leaves the led on, I'll double check the stubs just in case and add some more prints.

The stubs all seem to be correct and if I put the camera in multishot-NR mode with S3 JPEG, I get enough memory to pass both memory tests (and all other tests as well, 4307 passed, 0 failed.).  So no other problems than the RecursiveLock stubs it seems.

dmilligan

  • Developer
  • Hero Member
  • *****
  • Posts: 3218
  • 60Da / 1100D / EOSM
Re: FIO_SeekSkipFile testing
« Reply #12 on: July 30, 2014, 12:19:15 AM »
Code: [Select]
ASSERT: FALSE
at Memory\Memory.c:188, task run_test
lv:0 mode:3


Magic Lantern version : Nightly.2014Jul29.1100D105
Mercurial changeset   : 3010ca328420 (1100D-FIO_SeekSkipFile) tip
Built on 2014-07-29 22:01:38 UTC by david@Artemis.local.
Free Memory  : 271K + 442K
 

https://bitbucket.org/dmilligan/magic-lantern/downloads/LOG000.LOG

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #13 on: July 30, 2014, 12:38:56 AM »
Can you check how far the test went? (what it printed right before crashing).

Looks like it tried to allocate something from AllocateMemory, but it failed. This shouldn't happen, because it checks both the free space and the max free region.

dmilligan

  • Developer
  • Hero Member
  • *****
  • Posts: 3218
  • 60Da / 1100D / EOSM
Re: FIO_SeekSkipFile testing
« Reply #14 on: July 30, 2014, 02:17:47 AM »
Code: [Select]
[FAIL] CACHEABLE(p) => 0x0
and then one more line that I can't read (it's covered by the memory error)

dmilligan

  • Developer
  • Hero Member
  • *****
  • Posts: 3218
  • 60Da / 1100D / EOSM
Re: FIO_SeekSkipFile testing
« Reply #15 on: July 30, 2014, 02:26:54 AM »
modified the test to stop after the FIO stuff to get the log:
Code: [Select]
[Pass] f = FIO_CreateFile("test.dat") => 0x3
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
       FIO_CloseFile(f)
[Pass] FIO_GetFileSize("test.dat", &size) => 0x0
[Pass] size => 0x20000
[Pass] p = (void*)_alloc_dma_memory(0x20000) => 0x40a7d7e4
[Pass] f = FIO_OpenFile("test.dat", O_RDONLY | O_SYNC) => 0x3
[Pass] FIO_ReadFile(f, p, 0x20000) => 0x20000
       FIO_CloseFile(f)
       _free_dma_memory(p)
[Pass] count => 0x3a98
[Pass] buf = fio_malloc(0x1000000) => 0x44600094
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] FIO_RemoveFile("test.dat") => 0x0

nikfreak

  • Developer
  • Hero Member
  • *****
  • Posts: 1197
Re: FIO_SeekSkipFile testing
« Reply #16 on: July 30, 2014, 08:17:44 AM »
All [PASS] on 6D!!!
70D.112 & 100D.101

zloe

  • New to the forum
  • *
  • Posts: 17
Re: FIO_SeekSkipFile testing
« Reply #17 on: July 30, 2014, 08:42:25 PM »
I have run the tests on my 650D.
The FIO Tests run all OK but afterwords the test crashes and I did not get a logfile.
Now I simply skipped the rest of the tests.
Result is:
Code: [Select]
[Pass] f = FIO_CreateFile("test.dat") => 0x3
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
       FIO_CloseFile(f)
[Pass] FIO_GetFileSize("test.dat", &size) => 0x0
[Pass] size => 0x20000
[Pass] p = (void*)_alloc_dma_memory(0x20000) => 0x407f5c24
[Pass] f = FIO_OpenFile("test.dat", O_RDONLY | O_SYNC) => 0x3
[Pass] FIO_ReadFile(f, p, 0x20000) => 0x20000
       FIO_CloseFile(f)
       _free_dma_memory(p)
[Pass] count => 0x3a98
[Pass] buf = fio_malloc(0x1000000) => 0x4a104094
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] FIO_RemoveFile("test.dat") => 0x0

Now I have to find out how to create a pull request.
If someone else is faster in adding the change and creating a pull request here is the changed line in stubs.S
Code: [Select]
NSTUB(0xFF34276C,  FIO_SeekSkipFile) 
EOS 6D, EOS 650D both with ML, EOS 80D (no ML, ... yet)

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #18 on: July 30, 2014, 08:48:14 PM »
The tests that fail are probably allocating more memory than it's available on 650D (24MB or so). You could try lower numbers, as others did earlier in this thread.

(I should lower the numbers too, probably the values that worked on 1100D should be fine on all cameras)

zloe

  • New to the forum
  • *
  • Posts: 17
Re: FIO_SeekSkipFile testing
« Reply #19 on: July 30, 2014, 10:07:04 PM »
Hm,
the last test that run was
Code: [Select]
            /* this one should not overrun */
            timer_func = 0;
            TEST_TRY_FUNC_CHECK(SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0), % 2 == 0);
The memory allocation takes place later in the test. still I reduced the value but it did not have any effect.

I also tried to skip the FIO tests and see if then the tests succeed. They do not. They crash at various points during the timer tests.
Anything I can try to narrow that down?

I created a pull request now for the FIO_SeekSkipFile.

EOS 6D, EOS 650D both with ML, EOS 80D (no ML, ... yet)

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #20 on: July 30, 2014, 10:16:25 PM »
Timer arguments are pretty tight, don't try to change them. Sometimes the failures here can be ignored, but crashes shouldn't happen.

Did this test with SetHPTimerAfterNow succeed?

You could add some delay (msleep) after each test (in the TEST_TRY_FUNC_CHECK macro), so you can follow what happens in real time.

zloe

  • New to the forum
  • *
  • Posts: 17
Re: FIO_SeekSkipFile testing
« Reply #21 on: July 30, 2014, 10:35:04 PM »
The mentioned test passes but it is the last thing displayed. After that the Camera does not respond any longer.
The msleep(500) I added in the macro made it worse. Now the Camera shuts down after the 2gig file has been created.
EOS 6D, EOS 650D both with ML, EOS 80D (no ML, ... yet)

escho

  • Contributor
  • Hero Member
  • *****
  • Posts: 563
Re: FIO_SeekSkipFile testing
« Reply #22 on: July 30, 2014, 10:40:28 PM »
600D:
Code: [Select]
[Pass] f = FIO_CreateFile("test.dat") => 0x3
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
[Pass] FIO_WriteFile(f, (void*)ROMBASEADDR, 0x10000) => 0x10000
       FIO_CloseFile(f)
[Pass] FIO_GetFileSize("test.dat", &size) => 0x0
[Pass] size => 0x20000
[Pass] p = (void*)_alloc_dma_memory(0x20000) => 0x409d293c
[Pass] f = FIO_OpenFile("test.dat", O_RDONLY | O_SYNC) => 0x3
[Pass] FIO_ReadFile(f, p, 0x20000) => 0x20000
       FIO_CloseFile(f)
       _free_dma_memory(p)
[Pass] count => 0x3a98
[Pass] buf = fio_malloc(0x1000000) => 0x422040a4
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000000
[Pass] f = FIO_OpenFile("test.dat", O_RDWR | O_SYNC) => 0x3
[Pass] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x82000000
[Pass] FIO_WriteFile(f, buf, 0x10) => 0x10
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x81fffff0
[Pass] FIO_WriteFile(f, buf, 0x30) => 0x30
[Pass] FIO_SeekSkipFile(f, 0x20, SEEK_SET) => 0x20
[Pass] FIO_SeekSkipFile(f, 0x30, SEEK_CUR) => 0x50
[Pass] FIO_SeekSkipFile(f, -0x20, SEEK_CUR) => 0x30
[Pass] FIO_GetFileSize_direct("test.dat") => 0x82000020
[Pass] FIO_RemoveFile("test.dat") => 0x0
...

Test complete 4547 passed, 0 failed
https://sternenkarten.com/
600D, 6D, openSUSE Tumbleweed

zloe

  • New to the forum
  • *
  • Posts: 17
Re: FIO_SeekSkipFile testing
« Reply #23 on: July 30, 2014, 10:42:44 PM »
Just tested the nightly build from 25th of July for the 650D, also there the api stub tests do not complete and the Camera hangs.
EOS 6D, EOS 650D both with ML, EOS 80D (no ML, ... yet)

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12564
Re: FIO_SeekSkipFile testing
« Reply #24 on: July 30, 2014, 10:43:06 PM »
If you comment out the timer section, does it pass?