Magic Lantern Forum

Developing Magic Lantern => General Development => Topic started by: a1ex on July 28, 2014, 01:40:28 PM

Title: FIO_SeekSkipFile testing
Post by: a1ex on July 28, 2014, 01:40:28 PM
After seeing the problems with FIO_SeekFile on large files (http://www.magiclantern.fm/forum/index.php?topic=12733.msg123507#msg123507) (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:

...
[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).

...
[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
Title: Re: FIO_SeekSkipFile testing
Post by: ayshih on July 28, 2014, 02:01:46 PM
All passes for 50D (all other tests too)

...
[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.
Title: Re: FIO_SeekSkipFile testing
Post by: Greg on July 28, 2014, 02:15:37 PM
500D :
[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
Title: Re: FIO_SeekSkipFile testing
Post by: ayshih on July 28, 2014, 03:27:31 PM
Quote from: ayshih on July 28, 2014, 02:01:46 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:

[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. 
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex on July 28, 2014, 03:31:09 PM
If we use int64_t in fio-ml.h, does it help?
Title: Re: FIO_SeekSkipFile testing
Post by: ayshih 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.
Title: Re: FIO_SeekSkipFile testing
Post by: Greg on July 28, 2014, 05:23:05 PM
500D : (commit 5e2dabf)
[FAIL] err = FIO_SeekSkipFile(f, (int64_t)0x8000000000000000, SEEK_CUR) => 0x30
[FAIL] err == (int64_t)0xFFFFFFFFFFFFFFFF => 0x0
Title: Re: FIO_SeekSkipFile testing
Post by: jpaana 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:


[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
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex on July 29, 2014, 10:42:09 AM
Stack overflow errors are not funny. Can you try to locate the test that causes it?
Title: Re: FIO_SeekSkipFile testing
Post by: jpaana on July 29, 2014, 02:22:07 PM
Quote from: a1ex on July 29, 2014, 10:42:09 AM
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.
Title: Re: FIO_SeekSkipFile testing
Post by: mk11174 on July 29, 2014, 02:49:54 PM
700D
[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
Title: Re: FIO_SeekSkipFile testing
Post by: jpaana on July 29, 2014, 02:52:22 PM
Quote from: jpaana on July 29, 2014, 02:22:07 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.
Title: Re: FIO_SeekSkipFile testing
Post by: dmilligan on July 30, 2014, 12:19:15 AM
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 [email protected].
Free Memory  : 271K + 442K


https://bitbucket.org/dmilligan/magic-lantern/downloads/LOG000.LOG
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex 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.
Title: Re: FIO_SeekSkipFile testing
Post by: dmilligan on July 30, 2014, 02:17:47 AM

[FAIL] CACHEABLE(p) => 0x0

and then one more line that I can't read (it's covered by the memory error)
Title: Re: FIO_SeekSkipFile testing
Post by: dmilligan on July 30, 2014, 02:26:54 AM
modified the test to stop after the FIO stuff to get the log:

[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
Title: Re: FIO_SeekSkipFile testing
Post by: nikfreak on July 30, 2014, 08:17:44 AM
All [PASS] on 6D!!!
Title: Re: FIO_SeekSkipFile testing
Post by: zloe 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:
[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
NSTUB(0xFF34276C,  FIO_SeekSkipFile) 
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex 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)
Title: Re: FIO_SeekSkipFile testing
Post by: zloe on July 30, 2014, 10:07:04 PM
Hm,
the last test that run was
            /* 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.

Title: Re: FIO_SeekSkipFile testing
Post by: a1ex 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.
Title: Re: FIO_SeekSkipFile testing
Post by: zloe 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.
Title: Re: FIO_SeekSkipFile testing
Post by: escho on July 30, 2014, 10:40:28 PM
600D:

[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
Title: Re: FIO_SeekSkipFile testing
Post by: zloe 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.
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex on July 30, 2014, 10:43:06 PM
If you comment out the timer section, does it pass?
Title: Re: FIO_SeekSkipFile testing
Post by: zloe on July 30, 2014, 10:58:52 PM
All tests pass besides this one:

       t0 = *(uint32_t*)0xC0242014 => 0x20902
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x70687
[FAIL] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x4d
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x2f
       Date/time: 2014/07/30 22:55:47
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x31

Title: Re: FIO_SeekSkipFile testing
Post by: a1ex on July 30, 2014, 11:14:40 PM
That one is no big deal, it's likely from high CPU usage.

We may have to double-check the timer stubs.
Title: Re: FIO_SeekSkipFile testing
Post by: a1ex on July 31, 2014, 12:18:39 PM
Found it - SetHPTimerNextTick was wrong. Can you try?

(this stub is used in mlv_play, so I guess nobody ever used this thing on 650D)
Title: Re: FIO_SeekSkipFile testing
Post by: vertigopix on July 31, 2014, 01:18:39 PM
All PASS on 60D

:)

https://drive.google.com/file/d/0B5V0Ovu4aQeQbi0wVGVmUXowM1k/edit?usp=sharing
Title: Re: FIO_SeekSkipFile testing
Post by: zloe on July 31, 2014, 11:19:07 PM
Just ran the tests on 650D again, now all tests pass!

Edit: I ran the stubs api tests (just to be precise).

Thanks!
So now we need to find the CancelDateTime stub.

This might take some time.
Title: Re: FIO_SeekSkipFile testing
Post by: vertigopix on August 03, 2014, 08:30:48 AM
Just received a nice EOS-M kit from my wife  :) :) :)

EOS-M crash here :

https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing (https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing)

Must remove battery to stop it.
No log written on the SD.

(And the ML menu disappear after 5-7 sec. but i think you know it)
Title: Re: FIO_SeekSkipFile testing
Post by: tob on August 03, 2014, 11:32:37 AM
Quote from: vertigopix on August 03, 2014, 08:30:48 AM
Just received a nice EOS-M kit from my wife  :) :) :)

EOS-M crash here :

https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing (https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing)

Must remove battery to stop it.
No log written on the SD.

(And the ML menu disappear after 5-7 sec. but i think you know it)

Exactly the same for me.
Title: Re: FIO_SeekSkipFile testing
Post by: jpaana on August 03, 2014, 11:29:30 PM
Quote from: vertigopix on August 03, 2014, 08:30:48 AM
Just received a nice EOS-M kit from my wife  :) :) :)

EOS-M crash here :

https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing (https://drive.google.com/file/d/0B5V0Ovu4aQeQOERTZ0VUUmV1WDA/edit?usp=sharing)

Must remove battery to stop it.
No log written on the SD.

(And the ML menu disappear after 5-7 sec. but i think you know it)

The default memory amounts are a bit too much for M without changing parameters to free up some memory. Try setting S3 JPEG and multishot-NR mode and you should have enough, at least mine does. Check from the memory available screen in debug menu how much you have, you need more than 64 megs free, with the settings above I get more than 90, but only 23 with my defaults.
Title: Re: FIO_SeekSkipFile testing
Post by: tob on August 04, 2014, 01:05:52 AM
2 test failed on 2 Aug build. EOS-M
STUBTEST.LOG
[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) => 0x408571a4
[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) => 0x42104094
[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
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0xbcb0
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x2
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0xbd1c
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0x1210a
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x13f
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0x116
[Pass] ABS((get_us_clock_value() - t0) - 110000) => 0x22a
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0x1210c
       msleep(80)
[FAIL] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 300000) => 0x295
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x26e
[FAIL] ABS((get_us_clock_value() - t0) - 310000) => 0x296f
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x1ded10
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x1deca0
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x1dec80
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       t0 = *(uint32_t*)0xC0242014 => 0x3631
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x3fd90
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x3
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x10
       Date/time: 2014/08/04 00:05:16
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x11
[Pass] MOD(s1-s0, 60) => 0x1
[Pass] MOD(s1-s0, 60) => 0x1
       m0 = MALLOC_FREE_MEMORY => 0x2c4a8
[Pass] p = (void*)_malloc(50*1024) => 0x144a90
[Pass] CACHEABLE(p) => 0x144a90
       m1 = MALLOC_FREE_MEMORY => 0x1fc98
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x2c4a8
[Pass] ABS((m0-m1) - 50*1024) => 0x10
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x361a1c
[Pass] p = (void*)_AllocateMemory(256*1024) => 0x857164
[Pass] CACHEABLE(p) => 0x857164
       m1 = GetFreeMemForAllocateMemory() => 0x321a10
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x361a1c
[Pass] ABS((m0-m1) - 256*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x2c4a8
       m02 = GetFreeMemForAllocateMemory() => 0x361a1c
[Pass] p = (void*)_alloc_dma_memory(256*1024) => 0x408571a4
[Pass] UNCACHEABLE(p) => 0x408571a4
[Pass] CACHEABLE(p) => 0x8571a4
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x408571a4
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(24*1024*1024) => 0x4214c0bc
[Pass] UNCACHEABLE(p) => 0x4214c0bc
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x2c4a8
       m12 = GetFreeMemForAllocateMemory() => 0x361a1c
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(24*1024*1024) => 0x141500
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1800000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x141528
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1800000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4214c0b8
[Pass] UNCACHEABLE(p) => 0x4214c0b8
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x11fb00
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x2000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb28
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4214c0b8
[Pass] UNCACHEABLE(p) => 0x4214c0b8
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(64*1024*1024) => 0x11fb00
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x2
[Pass] suite->size => 0x4000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb28
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4214c0b8
[Pass] UNCACHEABLE(p) => 0x4214c0b8
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fb88
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4414c0c4
[Pass] UNCACHEABLE(p) => 0x4414c0c4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x4000000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x11fb00
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x5
[Pass] suite->size => 0x5f00000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb28
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4214c0b8
[Pass] UNCACHEABLE(p) => 0x4214c0b8
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fb88
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4414c0c4
[Pass] UNCACHEABLE(p) => 0x4414c0c4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fbc0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5eb0000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4614c0d0
[Pass] UNCACHEABLE(p) => 0x4614c0d0
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fbf8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5ee0000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fc30
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5f00000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x419ff0a4
[Pass] UNCACHEABLE(p) => 0x419ff0a4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x5f00000
       shoot_free_suite(suite); suite = 0; chunk = 0;
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(500);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] MEM(dialog->type) => 0x6e6144
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0x8d9a00b0
[Pass] test_task_created => 0x1
[Pass] get_task_name_from_id(get_current_task()) => 'run_test'
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 2) => 0x8d9c00b6
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xABCDEF0) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xBADCAFE) => 0xd
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0xabcdef0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_count((void*)1, &mqcount) => 0x7
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0x8d9e0242
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0x8da000be
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0
Title: Re: FIO_SeekSkipFile testing
Post by: josepvm on August 04, 2014, 10:35:20 AM
I also get similar errors in 500D,  03 August build from unified branch. I get 3 errors:


[FAIL] ABS((get_us_clock_value() - t0) - 110000) => 0x401
...
[FAIL] ABS(DeltaT(timer_time, t0) - 300000) => 0x47c
[FAIL] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x446


The complete log:


[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) => 0x40a2b278
[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) => 0x4210c0ac
[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
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x3f18
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x8
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x3f3e
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0x13cc
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x14b
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0x115
[FAIL] ABS((get_us_clock_value() - t0) - 110000) => 0x401
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0x13ce
       msleep(80)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[FAIL] ABS(DeltaT(timer_time, t0) - 300000) => 0x47c
[FAIL] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x446
[Pass] ABS((get_us_clock_value() - t0) - 310000) => 0x141
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x17c440
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x17c3c0
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x17c3a0
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       t0 = *(uint32_t*)0xC0242014 => 0xf62a2
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x32acb
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x3
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x2b
       Date/time: 2014/08/04 09:55:43
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x2c
[Pass] MOD(s1-s0, 60) => 0x1
[Pass] MOD(s1-s0, 60) => 0x1
       m0 = MALLOC_FREE_MEMORY => 0x23150
[Pass] p = (void*)_malloc(50*1024) => 0x102f30
[Pass] CACHEABLE(p) => 0x102f30
       m1 = MALLOC_FREE_MEMORY => 0x16950
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x23150
[Pass] ABS((m0-m1) - 50*1024) => 0x0
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x30b328
[Pass] p = (void*)_AllocateMemory(256*1024) => 0xa2b238
[Pass] CACHEABLE(p) => 0xa2b238
       m1 = GetFreeMemForAllocateMemory() => 0x2cb31c
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x30b328
[Pass] ABS((m0-m1) - 256*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x23150
       m02 = GetFreeMemForAllocateMemory() => 0x30b328
[Pass] p = (void*)_alloc_dma_memory(256*1024) => 0x40a2b278
[Pass] UNCACHEABLE(p) => 0x40a2b278
[Pass] CACHEABLE(p) => 0xa2b278
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x40a2b278
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(24*1024*1024) => 0x4c000068
[Pass] UNCACHEABLE(p) => 0x4c000068
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x23150
       m12 = GetFreeMemForAllocateMemory() => 0x30b328
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(24*1024*1024) => 0x1014e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1800000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x101508
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1800000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4c000064
[Pass] UNCACHEABLE(p) => 0x4c000064
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x1014e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1ae0000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x101508
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1ae0000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x44000064
[Pass] UNCACHEABLE(p) => 0x44000064
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(64*1024*1024) => 0x1014e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x4
[Pass] suite->size => 0x4000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x101508
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1324000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4210c088
[Pass] UNCACHEABLE(p) => 0x4210c088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101558
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1328000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42000064
[Pass] UNCACHEABLE(p) => 0x42000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101588
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2e08000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4c000064
[Pass] UNCACHEABLE(p) => 0x4c000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x1015b8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x44000064
[Pass] UNCACHEABLE(p) => 0x44000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x4000000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x1014e8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x9
[Pass] suite->size => 0x5f00000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x101508
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1324000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4210c088
[Pass] UNCACHEABLE(p) => 0x4210c088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101558
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x1328000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42000064
[Pass] UNCACHEABLE(p) => 0x42000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101588
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2e08000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x44000064
[Pass] UNCACHEABLE(p) => 0x44000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x1015b8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x48e8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4c000064
[Pass] UNCACHEABLE(p) => 0x4c000064
       chunk = GetNextMemoryChunk(suite, chunk) => 0x1015e8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4e04000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x45ae00e4
[Pass] UNCACHEABLE(p) => 0x45ae00e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101618
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5320000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4dae00e4
[Pass] UNCACHEABLE(p) => 0x4dae00e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101648
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x583c000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4bae00e4
[Pass] UNCACHEABLE(p) => 0x4bae00e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x101678
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5d58000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x49ae00e4
[Pass] UNCACHEABLE(p) => 0x49ae00e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x1016a8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5f00000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x47ae00e4
[Pass] UNCACHEABLE(p) => 0x47ae00e4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x5f00000
       shoot_free_suite(suite); suite = 0; chunk = 0;
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(500);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] MEM(dialog->type) => 0x414944
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0x6fe00ae
[Pass] test_task_created => 0x1
[Pass] get_task_name_from_id(get_current_task()) => 'run_test'
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 2) => 0x7000080
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xABCDEF0) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xBADCAFE) => 0xd
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0xabcdef0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_count((void*)1, &mqcount) => 0x7
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0x7020226
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0x704003a
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0


But the FIO_SeekSkipFile related section, shown by A1ex in the first post, seems Ok.

-------------------------
Update: The errors above seem related to lack of avalaible memory.

If I change camera quality adjustment from RAW to JPEG low resolution (Small resolution/Normal quality JPEG) the stubs API test completes with no errors.
And changing to raw again, the test completes Ok, also.

Comparing the setups, I see the main difference is "malloc" available memory. It was 130KB in the first test, the one that failed.
When changing to JPG low res, malloc value increases to 141 KB, and test completes OK. Then, changing to raw again, malloc still gives 140 Kb, and the test completes well also.

Other memory values do not change significatively when changing from raw to jpg. In fact, SRM available memory gets reduced, from 4x26 MB (for RAW only mode) to 3x26 MB when allowing jpg output. This has been already noticed in the SRM thread (http://www.magiclantern.fm/forum/index.php?topic=12528.msg121508#msg121508).


Title: Re: FIO_SeekSkipFile testing
Post by: vertigopix on August 05, 2014, 12:21:02 PM
EOS-M

Settings JPEG S3 and Normal NR all tests PASS.

[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) => 0x4085b24c
[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) => 0x42104094
[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
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x6636
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x4
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x66a4
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0xc8e2
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x12c
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0x107
[Pass] ABS((get_us_clock_value() - t0) - 110000) => 0x132
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0xc8e4
       msleep(80)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 300000) => 0x1a2
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x178
[Pass] ABS((get_us_clock_value() - t0) - 310000) => 0xff
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x1ded10
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x1deca0
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x1dec80
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       t0 = *(uint32_t*)0xC0242014 => 0xefb46
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x2c26c
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x3
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x10
       Date/time: 2014/08/05 12:07:16
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x11
[Pass] MOD(s1-s0, 60) => 0x1
[Pass] MOD(s1-s0, 60) => 0x1
       m0 = MALLOC_FREE_MEMORY => 0x2c490
[Pass] p = (void*)_malloc(50*1024) => 0x144470
[Pass] CACHEABLE(p) => 0x144470
       m1 = MALLOC_FREE_MEMORY => 0x1fc80
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x2c490
[Pass] ABS((m0-m1) - 50*1024) => 0x10
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x36e918
[Pass] p = (void*)_AllocateMemory(256*1024) => 0x85b20c
[Pass] CACHEABLE(p) => 0x85b20c
       m1 = GetFreeMemForAllocateMemory() => 0x32e90c
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x36e918
[Pass] ABS((m0-m1) - 256*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x2c490
       m02 = GetFreeMemForAllocateMemory() => 0x36e918
[Pass] p = (void*)_alloc_dma_memory(256*1024) => 0x4085b24c
[Pass] UNCACHEABLE(p) => 0x4085b24c
[Pass] CACHEABLE(p) => 0x85b24c
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x4085b24c
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(24*1024*1024) => 0x42104074
[Pass] UNCACHEABLE(p) => 0x42104074
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x2c490
       m12 = GetFreeMemForAllocateMemory() => 0x36e918
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(24*1024*1024) => 0x11fad8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1800000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb00
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1800000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x11fad8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x2000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb00
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(64*1024*1024) => 0x11fad8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x2
[Pass] suite->size => 0x4000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb00
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fb60
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4410407c
[Pass] UNCACHEABLE(p) => 0x4410407c
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x4000000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x11fad8
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x4
[Pass] suite->size => 0x5f00000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x11fb00
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fb60
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4410407c
[Pass] UNCACHEABLE(p) => 0x4410407c
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fb98
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5ef8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x46104088
[Pass] UNCACHEABLE(p) => 0x46104088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x11fbd0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5f00000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x419ff0a4
[Pass] UNCACHEABLE(p) => 0x419ff0a4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x5f00000
       shoot_free_suite(suite); suite = 0; chunk = 0;
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(500);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] MEM(dialog->type) => 0x6e6144
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0x78ce0004
[Pass] test_task_created => 0x1
[Pass] get_task_name_from_id(get_current_task()) => 'run_test'
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 2) => 0x78d000b6
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xABCDEF0) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xBADCAFE) => 0xd
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0xabcdef0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_count((void*)1, &mqcount) => 0x7
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0x78d20298
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0x78d4009e
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0
Title: Re: FIO_SeekSkipFile testing
Post by: dfort on July 26, 2015, 08:48:10 PM
EOSM.202

Reviving an old topic but I'm starting to work on a new stub for the EOS-M so I ran this test. I tried multiple cards and multiple builds multiple times. Slow cards, old 1GB & 2GB fat16 formatted, show read/write failures which is probably expected.

[FAIL] FIO_GetFileSize_direct("test.dat") => 0x39518000
[FAIL] FIO_SeekSkipFile(f, 0, SEEK_END) => 0x39518000
[FAIL] FIO_WriteFile(f, buf, 0x10) => 0xffffffff
[FAIL] FIO_SeekSkipFile(f, -0x20, SEEK_END) => 0x39517fe0
[FAIL] FIO_WriteFile(f, buf, 0x30) => 0xffffffff
[FAIL] FIO_GetFileSize_direct("test.dat") => 0x39518000


Everything passes on the last successful nightly, magiclantern-Nightly.2015Apr19.EOSM202 and on the latest unified branch. However on one pass I did get this error once (not repeatable) from a build of dm-spy-experiments:

       SW1(1,100)
[FAIL] HALFSHUTTER_PRESSED => 0x0
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0


Here's the full log from the current unified code, magiclantern-Nightly.2015Jul26.EOSM202. The only change was to bypass the intentional break on the EOSM (http://www.magiclantern.fm/forum/index.php?topic=14959.msg148768#msg148768). Just thought it might be useful because there there are several differences from the one posted by vertigopix almost a year ago:

[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) => 0x40abab50
[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) => 0x42104094
[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
[Pass] SetTimerAfter(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x2fe4
       msleep(900)
[Pass] timer_func => 0x0
       msleep(200)
[Pass] timer_func => 0x1
[Pass] ABS((timer_time/1000 - t0) - 1000) => 0x7
[Pass] ABS((timer_arg - ta0) - 1000) => 0xa
[Pass] timer = SetTimerAfter(1000, timer_cbr, overrun_cbr, 0) => 0x3050
       msleep(400)
       CancelTimer(timer)
[Pass] timer_func => 0x0
       msleep(1500)
[Pass] timer_func => 0x0
[Pass] SetHPTimerAfterNow(0, timer_cbr, overrun_cbr, 0) => 0x15
[Pass] timer_func => 0x2
[Pass] SetHPTimerAfterNow(100000, timer_cbr, overrun_cbr, 0) => 0x95fc
       msleep(90)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 100000) => 0x12c
[Pass] ABS(DeltaT(timer_arg, ta0) - 100000) => 0x101
[Pass] ABS((get_us_clock_value() - t0) - 110000) => 0x310
[Pass] SetHPTimerAfterNow(90000, next_tick_cbr, overrun_cbr, 0) => 0x95fe
       msleep(80)
[Pass] timer_func => 0x0
       msleep(20)
[Pass] timer_func => 0x3
       msleep(80)
[Pass] timer_func => 0x3
       msleep(20)
[Pass] timer_func => 0x1
[Pass] ABS(DeltaT(timer_time, t0) - 300000) => 0x3a1
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x379
[Pass] ABS((get_us_clock_value() - t0) - 310000) => 0x3a2
[Pass] MEM(&CancelDateTimer) => 0xe92d4010
[Pass] strlen("abc") => 0x3
[Pass] strlen("qwertyuiop") => 0xa
[Pass] strlen("") => 0x0
[Pass] strcpy(msg, "hi there") => 0x1de908
[Pass] msg => 'hi there'
[Pass] snprintf(a, sizeof(a), "foo") => 0x3
[Pass] snprintf(b, sizeof(b), "foo") => 0x3
[Pass] strcmp(a, b) => 0x0
[Pass] snprintf(a, sizeof(a), "bar") => 0x3
[Pass] snprintf(b, sizeof(b), "baz") => 0x3
[Pass] strcmp(a, b) => 0xfffffff8
[Pass] snprintf(a, sizeof(a), "Display") => 0x7
[Pass] snprintf(b, sizeof(b), "Defishing") => 0x9
[Pass] strcmp(a, b) => 0x4
[Pass] snprintf(buf, 3, "%d", 1234) => 0x2
[Pass] buf => '12'
[Pass] memcpy(foo, bar, 6) => 0x1de8a0
[Pass] foo => 'asdfghuiop'
[Pass] memset(bar, '*', 5) => 0x1de880
[Pass] bar => '*****hjkl;'
       bzero32(bar + 5, 5)
[Pass] bar => '****'
       t0 = *(uint32_t*)0xC0242014 => 0x4bf3d
       msleep(250)
       t1 = *(uint32_t*)0xC0242014 => 0x88204
[Pass] ABS(MOD(t1-t0, 1048576)/1000 - 250) => 0x4
       LoadCalendarFromRTC( &now )
       s0 = now.tm_sec => 0x37
       Date/time: 2015/07/26 10:59:55
       msleep(1500)
       LoadCalendarFromRTC( &now )
       s1 = now.tm_sec => 0x39
[Pass] MOD(s1-s0, 60) => 0x2
[Pass] MOD(s1-s0, 60) => 0x2
       m0 = MALLOC_FREE_MEMORY => 0x2bff0
[Pass] p = (void*)_malloc(50*1024) => 0x1445a0
[Pass] CACHEABLE(p) => 0x1445a0
       m1 = MALLOC_FREE_MEMORY => 0x1f7e0
       _free(p)
       m2 = MALLOC_FREE_MEMORY => 0x2bff0
[Pass] ABS((m0-m1) - 50*1024) => 0x10
[Pass] ABS(m0-m2) => 0x0
       m0 = GetFreeMemForAllocateMemory() => 0x36698c
[Pass] p = (void*)_AllocateMemory(256*1024) => 0x863940
[Pass] CACHEABLE(p) => 0x863940
       m1 = GetFreeMemForAllocateMemory() => 0x326980
       _FreeMemory(p)
       m2 = GetFreeMemForAllocateMemory() => 0x36698c
[Pass] ABS((m0-m1) - 256*1024) => 0xc
[Pass] ABS(m0-m2) => 0x0
       m01 = MALLOC_FREE_MEMORY => 0x2bff0
       m02 = GetFreeMemForAllocateMemory() => 0x36698c
[Pass] p = (void*)_alloc_dma_memory(256*1024) => 0x40863980
[Pass] UNCACHEABLE(p) => 0x40863980
[Pass] CACHEABLE(p) => 0x863980
[Pass] UNCACHEABLE(CACHEABLE(p)) => 0x40863980
       _free_dma_memory(p)
[Pass] p = (void*)_shoot_malloc(24*1024*1024) => 0x42104074
[Pass] UNCACHEABLE(p) => 0x42104074
       _shoot_free(p)
       m11 = MALLOC_FREE_MEMORY => 0x2bff0
       m12 = GetFreeMemForAllocateMemory() => 0x36698c
[Pass] ABS(m01-m11) => 0x0
[Pass] ABS(m02-m12) => 0x0
[Pass] suite = shoot_malloc_suite_contig(24*1024*1024) => 0x141a20
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x1800000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x141a48
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x1800000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite_contig(0) => 0x141a20
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x1
[Pass] suite->size => 0x2000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x141a48
[Pass] chunk->signature => 'MemChunk'
[Pass] chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(64*1024*1024) => 0x141a20
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x2
[Pass] suite->size => 0x4000000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x141a48
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x141aa8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4410407c
[Pass] UNCACHEABLE(p) => 0x4410407c
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x4000000
       shoot_free_suite(suite); suite = 0; chunk = 0;
[Pass] suite = shoot_malloc_suite(0) => 0x141a20
[Pass] suite->signature => 'MemSuite'
[Pass] suite->num_chunks => 0x4
[Pass] suite->size => 0x5f00000
[Pass] chunk = GetFirstChunkFromSuite(suite) => 0x141a48
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x2000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x42104070
[Pass] UNCACHEABLE(p) => 0x42104070
       chunk = GetNextMemoryChunk(suite, chunk) => 0x141aa8
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x4000000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x4410407c
[Pass] UNCACHEABLE(p) => 0x4410407c
       chunk = GetNextMemoryChunk(suite, chunk) => 0x141ae0
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5ef8000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x46104088
[Pass] UNCACHEABLE(p) => 0x46104088
       chunk = GetNextMemoryChunk(suite, chunk) => 0x141b18
[Pass] chunk->signature => 'MemChunk'
[Pass] total += chunk->size => 0x5f00000
[Pass] p = GetMemoryAddressOfMemoryChunk(chunk) => 0x419ff0a4
[Pass] UNCACHEABLE(p) => 0x419ff0a4
       chunk = GetNextMemoryChunk(suite, chunk) => 0x0
[Pass] total => 0x5f00000
       shoot_free_suite(suite); suite = 0; chunk = 0;
       EngDrvOut(LCD_Palette[0], 0x1234)
[Pass] shamem_read(LCD_Palette[0]) => 0x1234
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       call("TurnOffDisplay")
[Pass] DISPLAY_IS_ON => 0x0
       call("TurnOnDisplay")
[Pass] DISPLAY_IS_ON => 0x1
       SetGUIRequestMode(1); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x1
       SetGUIRequestMode(2); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x2
       SetGUIRequestMode(0); msleep(1000);
[Pass] CURRENT_DIALOG_MAYBE => 0x0
[Pass] display_idle() => 0x1
       GUI_Control(BGMT_PLAY, 0, 0, 0); msleep(500);
[Pass] PLAY_MODE => 0x1
[Pass] MENU_MODE => 0x0
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x1
[Pass] PLAY_MODE => 0x0
[Pass] MEM(dialog->type) => 0x6e6144
       GUI_Control(BGMT_MENU, 0, 0, 0); msleep(500);
[Pass] MENU_MODE => 0x0
[Pass] PLAY_MODE => 0x0
       task_create("test", 0x1c, 0x1000, test_task, 0) => 0x747600b0
[Pass] test_task_created => 0x1
[Pass] get_task_name_from_id(get_current_task()) => 'run_test'
[Pass] mq = mq ? mq : (void*)msg_queue_create("test", 2) => 0x747800b6
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0x1234567) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xABCDEF0) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_post(mq, 0xBADCAFE) => 0xd
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0x1234567
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x0
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] m => 0xabcdef0
[Pass] msg_queue_receive(mq, (struct event **) &m, 500) => 0x9
[Pass] msg_queue_count(mq, &mqcount) => 0x0
[Pass] msg_queue_count((void*)1, &mqcount) => 0x7
[Pass] sem = sem ? sem : create_named_semaphore("test", 1) => 0x747a02b8
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] take_semaphore(sem, 500) => 0x9
[Pass] give_semaphore(sem) => 0x0
[Pass] take_semaphore(sem, 500) => 0x0
[Pass] give_semaphore(sem) => 0x0
[Pass] rlock = rlock ? rlock : CreateRecursiveLock(0) => 0x747c0040
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] AcquireRecursiveLock(rlock, 500) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0x0
[Pass] ReleaseRecursiveLock(rlock) => 0xf
       SW1(1,100)
[Pass] HALFSHUTTER_PRESSED => 0x1
       SW1(0,100)
[Pass] HALFSHUTTER_PRESSED => 0x0


[EDIT - Here's another Fail I got once with the latest unified.]

[FAIL] ABS(DeltaT(timer_time, t0) - 300000) => 0x414
[Pass] ABS(DeltaT(timer_arg, ta0) - 300000) => 0x3e6
[Pass] ABS((get_us_clock_value() - t0) - 310000) => 0x7c