jruby192 vs ruby193p0 input errors and latency on osx lion 10.7.3 and windows 7 64-bit

[sdj]

A loop dumping received MIDI data on JRuby 1.9.2 is returning strange data for the bottom of my controller sliders and knobs (i.e.: if I turn the knobs or pull the sliders towards zero). (Both jruby and ruby where installed via brew.):

$ jruby --1.9 -v
jruby 1.6.6 (ruby-1.9.2-p312) (2012-01-30 5673572) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_29) [darwin-x86_64-java]
$ jruby --1.9 input.rb
java
1.9.2
2012-01-30

Select a MIDI input...
0) Fast Track Ultra
1) Akai APC40
5) Real Time Sequencer
> 1
send some MIDI to your input now...
[{:data=>[176, 14, 33], :timestamp=>15042.999982833862}]
[{:data=>[176, 14, 32], :timestamp=>15138.999938964844}]
[{:data=>[176, 14, 31], :timestamp=>16249.000072479248}]
[{:data=>[176, 14, 30], :timestamp=>16311.000108718872}]
[{:data=>[176, 14, 29], :timestamp=>16497.999906539917}]
[{:data=>[176, 14, 28], :timestamp=>16584.00011062622}]
[{:data=>[176, 14, 27], :timestamp=>16696.00009918213}]
[{:data=>[176, 14, 26], :timestamp=>16854.000091552734}]
[{:data=>[176, 14, 25], :timestamp=>17042.999982833862}]
[{:data=>[176, 14, 24], :timestamp=>17094.000101089478}]
[{:data=>[176, 14, 23], :timestamp=>17194.000005722046}]
[{:data=>[176, 14, 22], :timestamp=>17332.99994468689}]
[{:data=>[176, 14, 21], :timestamp=>17473.000049591064}]
[{:data=>[176, 14, 20], :timestamp=>17614.00008201599}]
[{:data=>[176, 14, 19], :timestamp=>17703.999996185303}]
[{:data=>[176, 14, 18], :timestamp=>17785.00008583069}]
[{:data=>[176, 14, 17], :timestamp=>17884.000062942505}]
[{:data=>[176, 14, 16], :timestamp=>17983.999967575073}]
[{:data=>[0, 235, 240], :timestamp=>18134.000062942505}]
[{:data=>[0, 235, 224], :timestamp=>18394.00005340576}]
[{:data=>[0, 235, 208], :timestamp=>18575.000047683716}]
[{:data=>[0, 235, 192], :timestamp=>18834.00011062622}]
[{:data=>[0, 235, 176], :timestamp=>19184.00001525879}]
[{:data=>[0, 235, 160], :timestamp=>19283.999919891357}]
[{:data=>[0, 235, 144], :timestamp=>19533.999919891357}]
[{:data=>[0, 235, 128], :timestamp=>19927.000045776367}]
[{:data=>[0, 235, 96], :timestamp=>20043.999910354614}]
[{:data=>[0, 235, 80], :timestamp=>20184.99994277954}]
[{:data=>[0, 235, 64], :timestamp=>20394.999980926514}]
[{:data=>[0, 235, 48], :timestamp=>20555.000066757202}]
[{:data=>[0, 235, 32], :timestamp=>20694.000005722046}]
[{:data=>[0, 235, 16], :timestamp=>21114.00008201599}]
[{:data=>[0, 235], :timestamp=>21483.999967575073}]
^C
$

For comparison, ruby 1.9.3p0 running simultaneously (same behaviour if only running one or the other) -- this version also throw exception on ^C that JRuby version does not, and is quite chunky outputting received data compared to the JRuby version (I'm not sure how to measure that to prove it -- unless the number of elements in the dumped arrays is indicative?):

$ ruby -v
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-darwin11.3.0]
$ ruby input.rb
x86_64-darwin11.3.0
1.9.3
2011-10-30

Select a MIDI input...
0) M-Audio Fast Track Ultra
2) Akai Akai APC40
> 2
send some MIDI to your input now...
[{:data=>[176, 14, 33], :timestamp=>6656.177759170532},
 {:data=>[176, 14, 32], :timestamp=>6656.36682510376}]
[{:data=>[176, 14, 31], :timestamp=>7866.124629974365},
 {:data=>[176, 14, 30], :timestamp=>7866.4116859436035}]
[{:data=>[176, 14, 29], :timestamp=>8123.588800430298},
 {:data=>[176, 14, 28], :timestamp=>8123.771905899048}]
[{:data=>[176, 14, 27], :timestamp=>8411.648750305176},
 {:data=>[176, 14, 26], :timestamp=>8411.79871559143}]
[{:data=>[176, 14, 25], :timestamp=>8661.818742752075}]
[{:data=>[176, 14, 24], :timestamp=>8662.103652954102}]
[{:data=>[176, 14, 23], :timestamp=>8912.774801254272}]
[{:data=>[176, 14, 22], :timestamp=>8913.033962249756}]
[{:data=>[176, 14, 21], :timestamp=>9193.013668060303},
 {:data=>[176, 14, 20], :timestamp=>9193.187713623047}]
[{:data=>[176, 14, 19], :timestamp=>9430.135726928711},
 {:data=>[176, 14, 18], :timestamp=>9430.555820465088},
 {:data=>[176, 14, 17], :timestamp=>9430.671691894531}]
[{:data=>[176, 14, 16], :timestamp=>9703.298807144165},
 {:data=>[176, 14, 15], :timestamp=>9703.441858291626}]
[{:data=>[176, 14, 14], :timestamp=>10037.22882270813}]
[{:data=>[176, 14, 13], :timestamp=>10309.62586402893}]
[{:data=>[176, 14, 12], :timestamp=>10553.469896316528}]
[{:data=>[176, 14, 11], :timestamp=>10802.077770233154},
 {:data=>[176, 14, 10], :timestamp=>10802.196979522705}]
[{:data=>[176, 14, 9], :timestamp=>11152.296781539917}]
[{:data=>[176, 14, 8], :timestamp=>11542.020797729492}]
[{:data=>[176, 14, 6], :timestamp=>11765.419721603394},
 {:data=>[176, 14, 5], :timestamp=>11765.552759170532}]
[{:data=>[176, 14, 4], :timestamp=>12013.13066482544}]
[{:data=>[176, 14, 3], :timestamp=>12273.216009140015},
 {:data=>[176, 14, 2], :timestamp=>12273.362874984741}]
[{:data=>[176, 14, 1], :timestamp=>12821.009874343872}]
[{:data=>[176, 14, 0], :timestamp=>13143.155813217163}]
^C/usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/gems/1.9.1/gems/ffi-coremidi-0.1.4/lib/coremidi/source.rb:120:in `queued_messages?': Interrupt
    from /usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/gems/1.9.1/gems/ffi-coremidi-0.1.4/lib/coremidi/source.rb:26:in `gets'
    from /usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/gems/1.9.1/gems/unimidi-0.3.2/lib/unimidi/congruous_api_adapter.rb:186:in `gets'
    from /Users/sdj/Code/midi/midi.rb:39:in `block (2 levels) in poll_input'
    from /Users/sdj/Code/midi/midi.rb:38:in `loop'
    from /Users/sdj/Code/midi/midi.rb:38:in `block in poll_input'
    from /usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/gems/1.9.1/gems/unimidi-0.3.2/lib/unimidi/congruous_api_adapter.rb:26:in `open'
    from /Users/sdj/Code/midi/midi.rb:34:in `poll_input'
    from /Users/sdj/Code/midi/input.rb:8:in `<top (required)>'
    from /usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/1.9.1/rubygems/custom_require.rb:36:in `require'
    from /usr/local/Cellar/ruby/1.9.3-p0/lib/ruby/1.9.1/rubygems/custom_require.rb:36:in `require'
    from ./input_ruby193.rb:3:in `<main>'
$

input.rb:

require 'unimidi'
require 'pp'

def poll_input(input)
  input.open do |i|

    $stdout.puts "send some MIDI to your input now..."

    loop do
      m = i.gets
      yield(m)
    end

  end
end

puts RUBY_PLATFORM, RUBY_VERSION, RUBY_RELEASE_DATE

input = UniMIDI::Input.gets

poll_input(input) do |m|
  pp m
end

This is on Lion 10.7.3 on a late 2010 Mac Book Air.

Any ideas? Am I missing something?

Let me know if you need any more info. Thanks!

[arirusso]

The exception on ^C is normal... but I'll consider suppressing it

What do you mean by "ruby 1.9.3p0 running simultaneously (same behaviour if only running one or the other) "

I'll deal with the bad controller messages in JRuby first...that definitely looks like a bug in http://github.com/arirusso/midi-jruby

[sdj]

I mean that the two logs' output is from running the input loop on both ruby interpreters simultaneously, but that the symptoms (wrong controller messages and latency on ruby193) occur when running only one of them at a time as well.

I never had JRuby throw the exception, it only seems to happen on ruby193. Is that expected?

[arirusso]

OK.

Yes, it's just the default behavior of the interpreter.

[arirusso]

Hi,

I can't seem to reproduce the JRuby bug in my environment. Would you mind running the unimidi tests using JRuby and posting the output? I'm hoping that if you do, a clue as to what's wrong will pop up.

You should be able to just clone unimidi:

git clone git@github.com:arirusso/unimidi.git cd unimidi

and then while running JRuby, do

jruby --1.9 -S rake test

You'll be prompted to select an input and output -- just select two IAC devices that are connected to each other

Thank you!

[sdj]

Tests pass, but it hangs after the line "Test run options: --seed 10633" and doesn't return to the shell. I'm not sure how long that's supposed to take, but after a minute or so I just ^C and go straight back to the prompt.

$ git clone git@github.com:arirusso/unimidi.git
Cloning into 'unimidi'...
remote: Counting objects: 706, done.
remote: Compressing objects: 100% (432/432), done.
remote: Total 706 (delta 384), reused 588 (delta 266)
Receiving objects: 100% (706/706), 74.97 KiB | 51 KiB/s, done.
Resolving deltas: 100% (384/384), done.
$ cd unimidi
$ git rev-parse HEAD
ddad882d82e697bd4ed708169305fe9dfde15bca
$ jruby --1.9 -S rake test
(in /Users/sdj/Code/unimidi)
/usr/local/Cellar/jruby/1.6.6/libexec/bin/jruby -I"lib:test" "/usr/local/Cellar/jruby/1.6.6/libexec/lib/ruby/1.9/rake/rake_test_loader.rb" "test/test_congruous_api_adapter.rb" "test/test_input_buffer.rb" "test/test_io.rb" "test/test_platform.rb" "test/test_selectors.rb" 

Select a MIDI input...
0) IAC Bus 1
3) Real Time Sequencer
> 0

Select a MIDI output...
1) IAC Bus 1
2) Real Time Sequencer
4) Java Sound Synthesizer
> 1
Loaded suite /usr/local/Cellar/jruby/1.6.6/libexec/lib/ruby/1.9/rake/rake_test_loader
Started
..sending: [144, 100, 100]
received: [144, 100, 100]
sending: [144, 43, 100]
received: [144, 100, 100, 144, 43, 100]
sending: [144, 76, 100]
received: [144, 100, 100, 144, 43, 100, 144, 76, 100]
sending: [144, 60, 100]
received: [144, 100, 100, 144, 43, 100, 144, 76, 100, 144, 60, 100]
sending: [128, 100, 100]
received: [144, 100, 100, 144, 43, 100, 144, 76, 100, 144, 60, 100, 128, 100, 100]
.sending: [144, 100, 100]
received: [144, 100, 100]
sending: [144, 43, 100]
received: [144, 43, 100]
sending: [144, 76, 100]
received: [144, 76, 100]
sending: [144, 60, 100]
received: [144, 60, 100]
sending: [128, 100, 100]
received: [128, 100, 100]
.sending: "906440"
received: "906440"
sending: "804340"
received: "804340"
.sending: #<TestHelper::MIDIObj:0x43a544a5 @bytes=[144, 100, 100]>
received: [144, 100, 100]
sending: #<TestHelper::MIDIObj:0x54992725 @bytes=[144, 43, 100]>
received: [144, 43, 100]
sending: #<TestHelper::MIDIObj:0x593f5a2f @bytes=[144, 76, 100]>
received: [144, 76, 100]
sending: #<TestHelper::MIDIObj:0x7c6d75b6 @bytes=[144, 60, 100]>
received: [144, 60, 100]
sending: #<TestHelper::MIDIObj:0x64d1afd3 @bytes=[128, 100, 100]>
received: [128, 100, 100]
.............
Finished in 28.681000 seconds.

18 tests, 47 assertions, 0 failures, 0 errors, 0 skips

Test run options: --seed 10633
^C$

[sdj]

I repeated the original test with another device, an X-Session Pro, and same result: messages with values less than 16 are corrupt under jruby.

Another thing I noticed, is jruby is not detecting the device name/manufacturer but ruby is:

jruby 1.9.2:

Select a MIDI input...
0) IAC Bus 1
1) Akai APC40
2) Port 1
3) Port 2
8) Real Time Sequencer
> 2

ruby 1.9.3:

Select a MIDI input...
0) Apple Inc. IAC Driver
2) Akai Akai APC40
4) Evolution Electronics Ltd. USB X-Session
6) Evolution Electronics Ltd. USB X-Session
> 4

And the message corruption is the same with the XSP as with the APC40 I used in the original bug report, messages with controller values < 16 appear corrupted:

jruby 1.9.2:

[{:data=>[176, 12, 17], :timestamp=>12247.999906539917}]
[{:data=>[176, 12, 16], :timestamp=>12629.999876022339}]
[{:data=>[0, 203, 240], :timestamp=>13402.999877929688}]
[{:data=>[0, 203, 224], :timestamp=>13905.999898910522}]

ruby 1.9.3:

 {:data=>[176, 12, 17], :timestamp=>106901.39603614807},
 {:data=>[176, 12, 16], :timestamp=>106901.52192115784},
 {:data=>[176, 12, 15], :timestamp=>106901.65185928345},
 {:data=>[176, 12, 14], :timestamp=>106901.79085731506},

[arirusso]

Thanks! This is all helpful.

Basically what's happening is that interpreting null-termination on the raw data is broken. It's confusing 0 and null at some point. (I wrote the JRuby library very quickly and must have glossed over that) Will shoot for fixing it Sunday.

I'll check out the hanging too.

As far as the device names go, I'll check it out but we may be at the mercy of Java there

[sdj]

Here are the same tests on Windows 7 Ultimate 64-bit. The only difference here is that I could not run them simultaneously (out of memory error -- misreporting a locked input maybe?). Same value < 16 message corruption, but this time ruby 1.9.3 (from rubyinstaller.org) is noticeably higher latency than even ruby 1.9.3 on OSX (I slid the knob similar speeds for the jruby and ruby tests, and the latter was 500-700ms per sample displaying on the screen).

C:\Users\sdj\Code\midi>jruby --1.9 -v
jruby 1.6.7 (ruby-1.9.2-p312) (2012-02-22 3e82bc8) (Java HotSpot(TM) 64-Bit Server VM 1.7.0) [Windows 7-amd64-java]

C:\Users\sdj\Code\midi>jruby --1.9 input.rb
java
1.9.2
2012-02-22

Select a MIDI input...
1) USB X-Session
2) MIDIIN2 (USB X-Session)
7) Real Time Sequencer
> 1
send some MIDI to your input now...
[{:data=>[176, 12, 25], :timestamp=>1934.000015258789}]
[{:data=>[176, 12, 24], :timestamp=>2184.000015258789}]
[{:data=>[176, 12, 23], :timestamp=>2339.9999141693115}]
[{:data=>[176, 12, 22], :timestamp=>2434.000015258789}]
[{:data=>[176, 12, 21], :timestamp=>2635.999917984009}]
[{:data=>[176, 12, 20], :timestamp=>2730.0000190734863}]
[{:data=>[176, 12, 19], :timestamp=>2855.0000190734863}]
[{:data=>[176, 12, 18], :timestamp=>2963.9999866485596}]
[{:data=>[176, 12, 17], :timestamp=>3072.999954223633}]
[{:data=>[176, 12, 16], :timestamp=>3151.0000228881836}]
[{:data=>[0, 203, 240], :timestamp=>3229.0000915527344}]
[{:data=>[0, 203, 224], :timestamp=>3292.0000553131104}]
[{:data=>[0, 203, 208], :timestamp=>3338.0000591278076}]
[{:data=>[0, 203, 192], :timestamp=>3431.999921798706}]
[{:data=>[0, 203, 176], :timestamp=>3540.9998893737793}]
[{:data=>[0, 203, 160], :timestamp=>3634.999990463257}]
[{:data=>[0, 203, 144], :timestamp=>3697.000026702881}]
[{:data=>[0, 203, 128], :timestamp=>3759.999990463257}]
[{:data=>[0, 203, 112], :timestamp=>3805.999994277954}]
[{:data=>[0, 203, 96], :timestamp=>3884.000062942505}]
[{:data=>[0, 203, 80], :timestamp=>3930.999994277954}]
[{:data=>[0, 203, 64], :timestamp=>3993.99995803833}]
[{:data=>[0, 203, 48], :timestamp=>4055.999994277954}]
[{:data=>[0, 203, 32], :timestamp=>4118.000030517578}]
[{:data=>[0, 203, 16], :timestamp=>4180.999994277954}]
[{:data=>[0, 203], :timestamp=>4227.999925613403}]
^C

C:\Users\sdj\Code\midi>ruby -v
ruby 1.9.3p125 (2012-02-16) [i386-mingw32]
C:\Users\sdj\Code\midi>ruby input.rb
i386-mingw32
1.9.3
2012-02-16

Select a MIDI input...
0) USB X-Session
1) MIDIIN2 (USB X-Session)
> 0
send some MIDI to your input now...
[{:data=>[176, 12, 47], :timestamp=>3307}]
[{:data=>[176, 12, 46], :timestamp=>3681}]
[{:data=>[176, 12, 45], :timestamp=>4336}]
[{:data=>[176, 12, 44], :timestamp=>4992}]
[{:data=>[176, 12, 43], :timestamp=>5647}]
[{:data=>[176, 12, 42], :timestamp=>6302}]
[{:data=>[176, 12, 41], :timestamp=>6957}]
[{:data=>[176, 12, 40], :timestamp=>7612}]
[{:data=>[176, 12, 39], :timestamp=>8268}]
[{:data=>[176, 12, 38], :timestamp=>8923}]
[{:data=>[176, 12, 37], :timestamp=>9578}]
[{:data=>[176, 12, 36], :timestamp=>10233}]
[{:data=>[176, 12, 35], :timestamp=>10888}]
[{:data=>[176, 12, 34], :timestamp=>11544}]
[{:data=>[176, 12, 33], :timestamp=>12199}]
[{:data=>[176, 12, 32], :timestamp=>12854}]
[{:data=>[176, 12, 31], :timestamp=>13509}]
[{:data=>[176, 12, 30], :timestamp=>14164}]
[{:data=>[176, 12, 29], :timestamp=>14820}]
[{:data=>[176, 12, 28], :timestamp=>15475}]
[{:data=>[176, 12, 27], :timestamp=>16130}]
[{:data=>[176, 12, 26], :timestamp=>16785}]
[{:data=>[176, 12, 25], :timestamp=>17440}]
[{:data=>[176, 12, 24], :timestamp=>18096}]
[{:data=>[176, 12, 23], :timestamp=>18751}]
[{:data=>[176, 12, 22], :timestamp=>19406}]
[{:data=>[176, 12, 21], :timestamp=>20061}]
[{:data=>[176, 12, 20], :timestamp=>20716}]
[{:data=>[176, 12, 19], :timestamp=>21372}]
[{:data=>[176, 12, 18], :timestamp=>22027}]
[{:data=>[176, 12, 17], :timestamp=>22682}]
[{:data=>[176, 12, 16], :timestamp=>23337}]
[{:data=>[176, 12, 0], :timestamp=>23992}]
[{:data=>[176, 12, 0], :timestamp=>24648}]
[{:data=>[176, 12, 0], :timestamp=>25303}]
[{:data=>[176, 12, 0], :timestamp=>25958}]
[{:data=>[176, 12, 0], :timestamp=>26613}]
[{:data=>[176, 12, 0], :timestamp=>27268}]
[{:data=>[176, 12, 0], :timestamp=>27924}]
[{:data=>[176, 12, 0], :timestamp=>28579}]
[{:data=>[176, 12, 0], :timestamp=>29234}]
[{:data=>[176, 12, 0], :timestamp=>29889}]
[{:data=>[176, 12, 0], :timestamp=>30544}]
[{:data=>[176, 12, 0], :timestamp=>31200}]
[{:data=>[176, 12, 0], :timestamp=>31812}]
[{:data=>[176, 12, 0], :timestamp=>32421}]
[{:data=>[176, 12, 0], :timestamp=>33076}]
[{:data=>[176, 0], :timestamp=>33676}]
^C
C:/Ruby193/lib/ruby/gems/1.9.1/gems/midi-winmm-0.1.10/lib/midi-winmm/input.rb:107:in `queued_messages?': Interrupt
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/midi-winmm-0.1.10/lib/midi-winmm/input.rb:57:in `gets'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/unimidi-0.3.2-x86-mingw32/lib/unimidi/congruous_api_adapter.rb:186:in `gets'
        from input.rb:10:in `block (2 levels) in poll_input'
        from input.rb:9:in `loop'
        from input.rb:9:in `block in poll_input'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/unimidi-0.3.2-x86-mingw32/lib/unimidi/congruous_api_adapter.rb:26:in `open'
        from input.rb:5:in `poll_input'
        from input.rb:21:in `<main>'

[arirusso]

try updating your version of the midi-jruby gem to 0.0.12 -- the "< 16 data" jruby bug should be fixed.

Moving on to the other stuff...

[arirusso]

I'm going to break each of your issues up into different tickets and close this one

[sdj]

Confirmed working on osx lion 1.7.3 and win7 64-bit.

[arirusso]

nice! thanks for reporting it. on to the next...

[TronicLabs]

Here have big latency on Win7 x64 and hang on close.

C:\usr\bin>ruby -v
ruby 1.9.3p0 (2011-10-30) [i386-mswin32_90]

C:\usr\bin>ruby WinMM_test.rb
Select a MIDI input...
0) In From MIDI Yoke:  1
1) In From MIDI Yoke:  2
2) In From MIDI Yoke:  3
3) In From MIDI Yoke:  4
4) In From MIDI Yoke:  5
5) In From MIDI Yoke:  6
6) In From MIDI Yoke:  7
7) In From MIDI Yoke:  8
8) Multiface Midi
9) Akai MPK49
10) MIDIIN2 (Akai MPK49)
11) MIDIIN3 (Akai MPK49)
> 9
send some MIDI to your input now...
{:data=>[176, 26, 125], :timestamp=>1361}
{:data=>[176, 26, 122], :timestamp=>1696}
{:data=>[176, 26, 118], :timestamp=>2296}
{:data=>[176, 26, 114], :timestamp=>2896}
{:data=>[176, 26, 109], :timestamp=>3496}
{:data=>[176, 26, 104], :timestamp=>4096}
{:data=>[176, 26, 99], :timestamp=>4696}
{:data=>[176, 26, 94], :timestamp=>5296}
{:data=>[176, 26, 88], :timestamp=>5896}
{:data=>[176, 26, 83], :timestamp=>6496}
{:data=>[176, 26, 77], :timestamp=>7096}
{:data=>[176, 26, 69], :timestamp=>7696}
{:data=>[176, 26, 62], :timestamp=>8296}
{:data=>[176, 26, 56], :timestamp=>8896}
{:data=>[176, 26, 49], :timestamp=>9496}
{:data=>[176, 26, 43], :timestamp=>10096}
{:data=>[176, 26, 36], :timestamp=>10696}
{:data=>[176, 26, 29], :timestamp=>11296}
{:data=>[176, 26, 22], :timestamp=>11896}
{:data=>[176, 26, 16], :timestamp=>12496}
{:data=>[176, 26, 0], :timestamp=>13096}
{:data=>[176, 26, 0], :timestamp=>13696}
{:data=>[176, 26], :timestamp=>14296}"