FIO_SeekSkipFile testing

[a1ex]

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]

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.

[Greg]

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]

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. 

[a1ex]

If we use int64_t in fio-ml.h, does it help?

[ayshih]

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.

[Greg]

500D : (commit 5e2dabf)

Code: [Select]

[FAIL] err = FIO_SeekSkipFile(f, (int64_t)0x8000000000000000, SEEK_CUR) => 0x30
[FAIL] err == (int64_t)0xFFFFFFFFFFFFFFFF => 0x0

[jpaana]

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]

Stack overflow errors are not funny. Can you try to locate the test that causes it?

[jpaana]

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]

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

[jpaana]

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]

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]

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]

Code: [Select]

[FAIL] CACHEABLE(p) => 0x0
and then one more line that I can't read (it's covered by the memory error)

[dmilligan]

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]

All [PASS] on 6D!!!

[zloe]

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) 

[a1ex]

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]

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.

[a1ex]

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]

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.

[escho]

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

[zloe]

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.

[a1ex]

If you comment out the timer section, does it pass?